ggpo: don't call exit on assert. clean up logging
Don't call exit when an assertion fails, throw an exception instead. Log ggpo API errors. Deleted most ggpo logging methods and use flycast logging.
This commit is contained in:
parent
1ab4eb00c0
commit
d76dff8594
|
@ -1358,8 +1358,6 @@ if(NOT LIBRETRO)
|
|||
core/deps/ggpo/lib/ggpo/game_input.h
|
||||
core/deps/ggpo/lib/ggpo/input_queue.cpp
|
||||
core/deps/ggpo/lib/ggpo/input_queue.h
|
||||
core/deps/ggpo/lib/ggpo/log.cpp
|
||||
core/deps/ggpo/lib/ggpo/log.h
|
||||
core/deps/ggpo/lib/ggpo/main.cpp
|
||||
core/deps/ggpo/lib/ggpo/platform_linux.cpp
|
||||
core/deps/ggpo/lib/ggpo/platform_linux.h
|
||||
|
|
|
@ -579,26 +579,6 @@ GGPO_API GGPOErrorCode __cdecl ggpo_set_disconnect_timeout(GGPOSession *,
|
|||
GGPO_API GGPOErrorCode __cdecl ggpo_set_disconnect_notify_start(GGPOSession *,
|
||||
int timeout);
|
||||
|
||||
/*
|
||||
* ggpo_log --
|
||||
*
|
||||
* Used to write to the ggpo.net log. In the current versions of the
|
||||
* SDK, a log file is only generated if the "quark.log" environment
|
||||
* variable is set to 1. This will change in future versions of the
|
||||
* SDK.
|
||||
*/
|
||||
GGPO_API void __cdecl ggpo_log(GGPOSession *,
|
||||
const char *fmt, ...);
|
||||
/*
|
||||
* ggpo_logv --
|
||||
*
|
||||
* A varargs compatible version of ggpo_log. See ggpo_log for
|
||||
* more details.
|
||||
*/
|
||||
GGPO_API void __cdecl ggpo_logv(GGPOSession *,
|
||||
const char *fmt,
|
||||
va_list args);
|
||||
|
||||
/*
|
||||
* ggpo_send_message --
|
||||
*
|
||||
|
|
|
@ -20,7 +20,6 @@ struct GGPOSession {
|
|||
virtual GGPOErrorCode IncrementFrame(void) { return GGPO_OK; }
|
||||
virtual GGPOErrorCode DisconnectPlayer(GGPOPlayerHandle handle) { return GGPO_OK; }
|
||||
virtual GGPOErrorCode GetNetworkStats(GGPONetworkStats *stats, GGPOPlayerHandle handle) { return GGPO_OK; }
|
||||
virtual GGPOErrorCode Logv(const char *fmt, va_list list) { ::Logv(fmt, list); return GGPO_OK; }
|
||||
|
||||
virtual GGPOErrorCode SetFrameDelay(GGPOPlayerHandle player, int delay) { return GGPO_ERRORCODE_UNSUPPORTED; }
|
||||
virtual GGPOErrorCode SetDisconnectTimeout(int timeout) { return GGPO_ERRORCODE_UNSUPPORTED; }
|
||||
|
|
|
@ -130,12 +130,12 @@ Peer2PeerBackend::DoPoll(int timeout)
|
|||
total_min_confirmed = PollNPlayers(current_frame);
|
||||
}
|
||||
|
||||
Log("last confirmed frame in p2p backend is %d.\n", total_min_confirmed);
|
||||
Log("last confirmed frame in p2p backend is %d.", total_min_confirmed);
|
||||
if (total_min_confirmed >= 0) {
|
||||
ASSERT(total_min_confirmed != INT_MAX);
|
||||
if (_num_spectators > 0) {
|
||||
while (_next_spectator_frame <= total_min_confirmed) {
|
||||
Log("pushing frame %d to spectators.\n", _next_spectator_frame);
|
||||
Log("pushing frame %d to spectators.", _next_spectator_frame);
|
||||
|
||||
GameInput input;
|
||||
input.frame = _next_spectator_frame;
|
||||
|
@ -147,7 +147,7 @@ Peer2PeerBackend::DoPoll(int timeout)
|
|||
_next_spectator_frame++;
|
||||
}
|
||||
}
|
||||
Log("setting confirmed frame in sync to %d.\n", total_min_confirmed);
|
||||
Log("setting confirmed frame in sync to %d.", total_min_confirmed);
|
||||
_sync.SetLastConfirmedFrame(total_min_confirmed);
|
||||
}
|
||||
|
||||
|
@ -189,12 +189,12 @@ int Peer2PeerBackend::Poll2Players(int current_frame)
|
|||
if (!_local_connect_status[i].disconnected) {
|
||||
total_min_confirmed = MIN(_local_connect_status[i].last_frame, total_min_confirmed);
|
||||
}
|
||||
Log(" local endp: connected = %d, last_received = %d, total_min_confirmed = %d.\n", !_local_connect_status[i].disconnected, _local_connect_status[i].last_frame, total_min_confirmed);
|
||||
Log(" local endp: connected = %d, last_received = %d, total_min_confirmed = %d.", !_local_connect_status[i].disconnected, _local_connect_status[i].last_frame, total_min_confirmed);
|
||||
if (!queue_connected && !_local_connect_status[i].disconnected) {
|
||||
Log("disconnecting i %d by remote request.\n", i);
|
||||
Log("disconnecting i %d by remote request.", i);
|
||||
DisconnectPlayerQueue(i, total_min_confirmed);
|
||||
}
|
||||
Log(" total_min_confirmed = %d.\n", total_min_confirmed);
|
||||
Log(" total_min_confirmed = %d.", total_min_confirmed);
|
||||
}
|
||||
return total_min_confirmed;
|
||||
}
|
||||
|
@ -208,7 +208,7 @@ int Peer2PeerBackend::PollNPlayers(int current_frame)
|
|||
for (queue = 0; queue < _num_players; queue++) {
|
||||
bool queue_connected = true;
|
||||
int queue_min_confirmed = MAX_INT;
|
||||
Log("considering queue %d.\n", queue);
|
||||
Log("considering queue %d.", queue);
|
||||
for (i = 0; i < _num_players; i++) {
|
||||
// we're going to do a lot of logic here in consideration of endpoint i.
|
||||
// keep accumulating the minimum confirmed point for all n*n packets and
|
||||
|
@ -218,16 +218,16 @@ int Peer2PeerBackend::PollNPlayers(int current_frame)
|
|||
|
||||
queue_connected = queue_connected && connected;
|
||||
queue_min_confirmed = MIN(last_received, queue_min_confirmed);
|
||||
Log(" endpoint %d: connected = %d, last_received = %d, queue_min_confirmed = %d.\n", i, connected, last_received, queue_min_confirmed);
|
||||
Log(" endpoint %d: connected = %d, last_received = %d, queue_min_confirmed = %d.", i, connected, last_received, queue_min_confirmed);
|
||||
} else {
|
||||
Log(" endpoint %d: ignoring... not running.\n", i);
|
||||
Log(" endpoint %d: ignoring... not running.", i);
|
||||
}
|
||||
}
|
||||
// merge in our local status only if we're still connected!
|
||||
if (!_local_connect_status[queue].disconnected) {
|
||||
queue_min_confirmed = MIN(_local_connect_status[queue].last_frame, queue_min_confirmed);
|
||||
}
|
||||
Log(" local endp: connected = %d, last_received = %d, queue_min_confirmed = %d.\n", !_local_connect_status[queue].disconnected, _local_connect_status[queue].last_frame, queue_min_confirmed);
|
||||
Log(" local endp: connected = %d, last_received = %d, queue_min_confirmed = %d.", !_local_connect_status[queue].disconnected, _local_connect_status[queue].last_frame, queue_min_confirmed);
|
||||
|
||||
if (queue_connected) {
|
||||
total_min_confirmed = MIN(queue_min_confirmed, total_min_confirmed);
|
||||
|
@ -236,11 +236,11 @@ int Peer2PeerBackend::PollNPlayers(int current_frame)
|
|||
// so, we need to re-adjust. This can happen when we detect our own disconnect at frame n
|
||||
// and later receive a disconnect notification for frame n-1.
|
||||
if (!_local_connect_status[queue].disconnected || _local_connect_status[queue].last_frame > queue_min_confirmed) {
|
||||
Log("disconnecting queue %d by remote request.\n", queue);
|
||||
Log("disconnecting queue %d by remote request.", queue);
|
||||
DisconnectPlayerQueue(queue, queue_min_confirmed);
|
||||
}
|
||||
}
|
||||
Log(" total_min_confirmed = %d.\n", total_min_confirmed);
|
||||
Log(" total_min_confirmed = %d.", total_min_confirmed);
|
||||
}
|
||||
return total_min_confirmed;
|
||||
}
|
||||
|
@ -335,7 +335,7 @@ Peer2PeerBackend::SyncInput(void *values,
|
|||
GGPOErrorCode
|
||||
Peer2PeerBackend::IncrementFrame(void)
|
||||
{
|
||||
Log("End of frame (%d)...\n", _sync.GetFrameCount());
|
||||
Log("End of frame (%d)...", _sync.GetFrameCount());
|
||||
_sync.IncrementFrame();
|
||||
DoPoll(0);
|
||||
PollSyncEvents();
|
||||
|
@ -383,7 +383,7 @@ Peer2PeerBackend::OnUdpProtocolPeerEvent(UdpProtocol::Event &evt, int queue)
|
|||
|
||||
_sync.AddRemoteInput(queue, evt.u.input.input);
|
||||
// Notify the other endpoints which frame we received from a peer
|
||||
Log("setting remote connect status for queue %d to %d\n", queue, evt.u.input.input.frame);
|
||||
Log("setting remote connect status for queue %d to %d", queue, evt.u.input.input.frame);
|
||||
_local_connect_status[queue].last_frame = evt.u.input.input.frame;
|
||||
}
|
||||
break;
|
||||
|
@ -493,14 +493,14 @@ Peer2PeerBackend::DisconnectPlayer(GGPOPlayerHandle player)
|
|||
int current_frame = _sync.GetFrameCount();
|
||||
// xxx: we should be tracking who the local player is, but for now assume
|
||||
// that if the endpoint is not initalized, this must be the local player.
|
||||
Log("Disconnecting local player %d at frame %d by user request.\n", queue, _local_connect_status[queue].last_frame);
|
||||
Log("Disconnecting local player %d at frame %d by user request.", queue, _local_connect_status[queue].last_frame);
|
||||
for (int i = 0; i < _num_players; i++) {
|
||||
if (_endpoints[i].IsInitialized()) {
|
||||
DisconnectPlayerQueue(i, current_frame);
|
||||
}
|
||||
}
|
||||
} else {
|
||||
Log("Disconnecting queue %d at frame %d by user request.\n", queue, _local_connect_status[queue].last_frame);
|
||||
Log("Disconnecting queue %d at frame %d by user request.", queue, _local_connect_status[queue].last_frame);
|
||||
DisconnectPlayerQueue(queue, _local_connect_status[queue].last_frame);
|
||||
}
|
||||
return GGPO_OK;
|
||||
|
@ -514,16 +514,16 @@ Peer2PeerBackend::DisconnectPlayerQueue(int queue, int syncto)
|
|||
|
||||
_endpoints[queue].Disconnect();
|
||||
|
||||
Log("Changing queue %d local connect status for last frame from %d to %d on disconnect request (current: %d).\n",
|
||||
Log("Changing queue %d local connect status for last frame from %d to %d on disconnect request (current: %d).",
|
||||
queue, _local_connect_status[queue].last_frame, syncto, framecount);
|
||||
|
||||
_local_connect_status[queue].disconnected = 1;
|
||||
_local_connect_status[queue].last_frame = syncto;
|
||||
|
||||
if (syncto != GameInput::NullFrame && syncto < framecount) {
|
||||
Log("adjusting simulation to account for the fact that %d disconnected @ %d.\n", queue, syncto);
|
||||
Log("adjusting simulation to account for the fact that %d disconnected @ %d.", queue, syncto);
|
||||
_sync.AdjustSimulation(syncto);
|
||||
Log("finished adjusting simulation.\n");
|
||||
Log("finished adjusting simulation.");
|
||||
}
|
||||
|
||||
info.code = GGPO_EVENTCODE_DISCONNECTED_FROM_PEER;
|
||||
|
|
|
@ -92,7 +92,7 @@ SpectatorBackend::SyncInput(void *values,
|
|||
GGPOErrorCode
|
||||
SpectatorBackend::IncrementFrame(void)
|
||||
{
|
||||
Log("End of frame (%d)...\n", _next_input_to_send - 1);
|
||||
Log("End of frame (%d)...", _next_input_to_send - 1);
|
||||
DoPoll(0);
|
||||
PollUdpProtocolEvents();
|
||||
|
||||
|
|
|
@ -83,7 +83,6 @@ SyncTestBackend::SyncInput(void *values,
|
|||
int size,
|
||||
int *disconnect_flags)
|
||||
{
|
||||
BeginLog(false);
|
||||
if (_rollingback) {
|
||||
_last_input = _saved_frames.front().input;
|
||||
} else {
|
||||
|
@ -105,8 +104,7 @@ SyncTestBackend::IncrementFrame(void)
|
|||
_sync.IncrementFrame();
|
||||
_current_input.erase();
|
||||
|
||||
Log("End of frame(%d)...\n", _sync.GetFrameCount());
|
||||
EndLog();
|
||||
DEBUG_LOG(NETWORK, "End of frame(%d)...", _sync.GetFrameCount());
|
||||
|
||||
if (_rollingback) {
|
||||
return GGPO_OK;
|
||||
|
@ -171,47 +169,9 @@ SyncTestBackend::RaiseSyncError(const char *fmt, ...)
|
|||
#ifdef _WIN32
|
||||
OutputDebugStringA(buf);
|
||||
#endif
|
||||
EndLog();
|
||||
// DebugBreak();
|
||||
}
|
||||
|
||||
GGPOErrorCode
|
||||
SyncTestBackend::Logv(char *fmt, va_list list)
|
||||
{
|
||||
if (_logfp) {
|
||||
vfprintf(_logfp, fmt, list);
|
||||
}
|
||||
return GGPO_OK;
|
||||
}
|
||||
|
||||
void
|
||||
SyncTestBackend::BeginLog(int saving)
|
||||
{
|
||||
EndLog();
|
||||
|
||||
char filename[MAX_PATH];
|
||||
#ifdef _WIN32
|
||||
CreateDirectoryA("synclogs", NULL);
|
||||
#else
|
||||
mkdir("synclogs", 0755);
|
||||
#endif
|
||||
snprintf(filename, ARRAY_SIZE(filename), "synclogs/%s-%04d-%s.log",
|
||||
saving ? "state" : "log",
|
||||
_sync.GetFrameCount(),
|
||||
_rollingback ? "replay" : "original");
|
||||
|
||||
_logfp = fopen(filename, "w");
|
||||
}
|
||||
|
||||
void
|
||||
SyncTestBackend::EndLog()
|
||||
{
|
||||
if (_logfp) {
|
||||
fprintf(_logfp, "Closing log file.\n");
|
||||
fclose(_logfp);
|
||||
_logfp = NULL;
|
||||
}
|
||||
}
|
||||
void
|
||||
SyncTestBackend::LogSaveStates(SavedInfo &info)
|
||||
{
|
||||
|
|
|
@ -24,7 +24,6 @@ public:
|
|||
virtual GGPOErrorCode AddLocalInput(GGPOPlayerHandle player, void *values, int size);
|
||||
virtual GGPOErrorCode SyncInput(void *values, int size, int *disconnect_flags);
|
||||
virtual GGPOErrorCode IncrementFrame(void);
|
||||
virtual GGPOErrorCode Logv(char *fmt, va_list list);
|
||||
|
||||
protected:
|
||||
struct SavedInfo {
|
||||
|
@ -36,8 +35,6 @@ protected:
|
|||
};
|
||||
|
||||
void RaiseSyncError(const char *fmt, ...);
|
||||
void BeginLog(int saving);
|
||||
void EndLog();
|
||||
void LogSaveStates(SavedInfo &info);
|
||||
|
||||
protected:
|
||||
|
|
|
@ -8,7 +8,6 @@
|
|||
#include "game_input.h"
|
||||
|
||||
#include "ggpo_types.h"
|
||||
#include "log.h"
|
||||
|
||||
void
|
||||
GameInput::init(int iframe, char *ibits, int isize, int offset)
|
||||
|
@ -65,25 +64,23 @@ GameInput::log(char *prefix, bool show_frame) const
|
|||
size_t c = strlen(prefix);
|
||||
strcpy(buf, prefix);
|
||||
desc(buf + c, ARRAY_SIZE(buf) - c, show_frame);
|
||||
strcat(buf, "\n");
|
||||
Log(buf);
|
||||
Log("%s", buf);
|
||||
}
|
||||
|
||||
bool
|
||||
GameInput::equal(GameInput &other, bool bitsonly)
|
||||
{
|
||||
if (!bitsonly && frame != other.frame) {
|
||||
Log("frames don't match: %d, %d\n", frame, other.frame);
|
||||
Log("frames don't match: %d, %d", frame, other.frame);
|
||||
}
|
||||
if (size != other.size) {
|
||||
Log("sizes don't match: %d, %d\n", size, other.size);
|
||||
}
|
||||
if (memcmp(bits, other.bits, size)) {
|
||||
Log("bits don't match\n");
|
||||
Log("sizes don't match: %d, %d", size, other.size);
|
||||
}
|
||||
bool match = memcmp(bits, other.bits, size) == 0;
|
||||
if (!match)
|
||||
Log("bits don't match");
|
||||
ASSERT(size && other.size);
|
||||
return (bitsonly || frame == other.frame) &&
|
||||
size == other.size &&
|
||||
memcmp(bits, other.bits, size) == 0;
|
||||
size == other.size && match;
|
||||
}
|
||||
|
||||
|
|
|
@ -40,6 +40,7 @@ typedef short int16;
|
|||
typedef int int32;
|
||||
|
||||
#include "ggponet.h"
|
||||
#include "log/Log.h"
|
||||
#include <stdexcept>
|
||||
|
||||
class GGPOException : public std::runtime_error {
|
||||
|
@ -61,8 +62,6 @@ public:
|
|||
# error Unsupported platform
|
||||
#endif
|
||||
|
||||
#include "log.h"
|
||||
|
||||
/*
|
||||
* Macros
|
||||
*/
|
||||
|
@ -70,16 +69,14 @@ public:
|
|||
do { \
|
||||
if (!(x)) { \
|
||||
char assert_buf[1024]; \
|
||||
snprintf(assert_buf, sizeof(assert_buf) - 1, "Assertion: %s @ %s:%d (pid:%ld)", #x, __FILE__, __LINE__, (long)GGPOPlatform::GetProcessID()); \
|
||||
Log("%s\n", assert_buf); \
|
||||
Log("\n"); \
|
||||
Log("\n"); \
|
||||
Log("\n"); \
|
||||
GGPOPlatform::AssertFailed(assert_buf); \
|
||||
exit(0); \
|
||||
snprintf(assert_buf, sizeof(assert_buf) - 1, "Assertion: %s @ %s:%d", #x, __FILE__, __LINE__); \
|
||||
GGPOPlatform::AssertFailed(assert_buf); \
|
||||
throw GGPOException(assert_buf, GGPO_ERRORCODE_GENERAL_FAILURE); \
|
||||
} \
|
||||
} while (false)
|
||||
|
||||
#define Log(...) DEBUG_LOG(NETWORK, __VA_ARGS__)
|
||||
|
||||
#ifndef ARRAY_SIZE
|
||||
# define ARRAY_SIZE(a) (sizeof(a) / sizeof((a)[0]))
|
||||
#endif
|
||||
|
|
|
@ -48,7 +48,7 @@ InputQueue::Init(int id, int input_size)
|
|||
int
|
||||
InputQueue::GetLastConfirmedFrame()
|
||||
{
|
||||
Log("returning last confirmed frame %d.\n", _last_added_frame);
|
||||
Log("input q%d | returning last confirmed frame %d.", _id, _last_added_frame);
|
||||
return _last_added_frame;
|
||||
}
|
||||
|
||||
|
@ -67,21 +67,21 @@ InputQueue::DiscardConfirmedFrames(int frame)
|
|||
frame = MIN(frame, _last_frame_requested);
|
||||
}
|
||||
|
||||
Log("discarding confirmed frames up to %d (last_added:%d length:%d [head:%d tail:%d]).\n",
|
||||
Log("input q%d | discarding confirmed frames up to %d (last_added:%d length:%d [head:%d tail:%d]).", _id,
|
||||
frame, _last_added_frame, _length, _head, _tail);
|
||||
if (frame >= _last_added_frame) {
|
||||
_tail = _head;
|
||||
} else {
|
||||
int offset = frame - _inputs[_tail].frame + 1;
|
||||
|
||||
Log("difference of %d frames.\n", offset);
|
||||
Log("input q%d | difference of %d frames.", _id, offset);
|
||||
ASSERT(offset >= 0);
|
||||
|
||||
_tail = (_tail + offset) % INPUT_QUEUE_LENGTH;
|
||||
_length -= offset;
|
||||
}
|
||||
|
||||
Log("after discarding, new tail is %d (frame:%d).\n", _tail, _inputs[_tail].frame);
|
||||
Log("input q%d | after discarding, new tail is %d (frame:%d).", _id, _tail, _inputs[_tail].frame);
|
||||
ASSERT(_length >= 0);
|
||||
}
|
||||
|
||||
|
@ -90,7 +90,7 @@ InputQueue::ResetPrediction(int frame)
|
|||
{
|
||||
ASSERT(_first_incorrect_frame == GameInput::NullFrame || frame <= _first_incorrect_frame);
|
||||
|
||||
Log("resetting all prediction errors back to frame %d.\n", frame);
|
||||
Log("input q%d | resetting all prediction errors back to frame %d.", _id, frame);
|
||||
|
||||
/*
|
||||
* There's nothing really to do other than reset our prediction
|
||||
|
@ -116,7 +116,7 @@ InputQueue::GetConfirmedInput(int requested_frame, GameInput *input)
|
|||
bool
|
||||
InputQueue::GetInput(int requested_frame, GameInput *input)
|
||||
{
|
||||
Log("requesting input frame %d.\n", requested_frame);
|
||||
Log("input q%d | requesting input frame %d.", _id, requested_frame);
|
||||
|
||||
/*
|
||||
* No one should ever try to grab any input when we have a prediction
|
||||
|
@ -144,7 +144,7 @@ InputQueue::GetInput(int requested_frame, GameInput *input)
|
|||
offset = (offset + _tail) % INPUT_QUEUE_LENGTH;
|
||||
ASSERT(_inputs[offset].frame == requested_frame);
|
||||
*input = _inputs[offset];
|
||||
Log("returning confirmed frame number %d.\n", input->frame);
|
||||
Log("input q%d | returning confirmed frame number %d.", _id, input->frame);
|
||||
return true;
|
||||
}
|
||||
|
||||
|
@ -154,13 +154,13 @@ InputQueue::GetInput(int requested_frame, GameInput *input)
|
|||
* same thing they did last time.
|
||||
*/
|
||||
if (requested_frame == 0) {
|
||||
Log("basing new prediction frame from nothing, you're client wants frame 0.\n");
|
||||
Log("input q%d | basing new prediction frame from nothing, you're client wants frame 0.", _id);
|
||||
_prediction.erase();
|
||||
} else if (_last_added_frame == GameInput::NullFrame) {
|
||||
Log("basing new prediction frame from nothing, since we have no frames yet.\n");
|
||||
Log("input q%d | basing new prediction frame from nothing, since we have no frames yet.", _id);
|
||||
_prediction.erase();
|
||||
} else {
|
||||
Log("basing new prediction frame from previously added frame (queue entry:%d, frame:%d).\n",
|
||||
Log("input q%d | basing new prediction frame from previously added frame (queue entry:%d, frame:%d).", _id,
|
||||
PREVIOUS_FRAME(_head), _inputs[PREVIOUS_FRAME(_head)].frame);
|
||||
_prediction = _inputs[PREVIOUS_FRAME(_head)];
|
||||
}
|
||||
|
@ -176,7 +176,7 @@ InputQueue::GetInput(int requested_frame, GameInput *input)
|
|||
*/
|
||||
*input = _prediction;
|
||||
input->frame = requested_frame;
|
||||
Log("returning prediction frame number %d (%d).\n", input->frame, _prediction.frame);
|
||||
Log("input q%d | returning prediction frame number %d (%d).", _id, input->frame, _prediction.frame);
|
||||
|
||||
return false;
|
||||
}
|
||||
|
@ -186,7 +186,7 @@ InputQueue::AddInput(GameInput &input)
|
|||
{
|
||||
int new_frame;
|
||||
|
||||
Log("adding input frame number %d to queue.\n", input.frame);
|
||||
Log("input q%d | adding input frame number %d to queue.", _id, input.frame);
|
||||
|
||||
/*
|
||||
* These next two lines simply verify that inputs are passed in
|
||||
|
@ -216,7 +216,7 @@ InputQueue::AddInput(GameInput &input)
|
|||
void
|
||||
InputQueue::AddDelayedInputToQueue(GameInput &input, int frame_number)
|
||||
{
|
||||
Log("adding delayed input frame number %d to queue.\n", frame_number);
|
||||
Log("input q%d | adding delayed input frame number %d to queue.", _id, frame_number);
|
||||
|
||||
if (input.size != _prediction.size)
|
||||
throw GGPOException("Input size differs from peer", GGPO_ERRORCODE_INPUT_SIZE_DIFF);
|
||||
|
@ -246,7 +246,7 @@ InputQueue::AddDelayedInputToQueue(GameInput &input, int frame_number)
|
|||
* in GetFirstIncorrectFrame()
|
||||
*/
|
||||
if (_first_incorrect_frame == GameInput::NullFrame && !_prediction.equal(input, true)) {
|
||||
Log("frame %d does not match prediction. marking error.\n", frame_number);
|
||||
Log("input q%d | frame %d does not match prediction. marking error.", _id, frame_number);
|
||||
_first_incorrect_frame = frame_number;
|
||||
}
|
||||
|
||||
|
@ -257,7 +257,7 @@ InputQueue::AddDelayedInputToQueue(GameInput &input, int frame_number)
|
|||
* count up.
|
||||
*/
|
||||
if (_prediction.frame == _last_frame_requested && _first_incorrect_frame == GameInput::NullFrame) {
|
||||
Log("prediction is correct! dumping out of prediction mode.\n");
|
||||
Log("input q%d | prediction is correct! dumping out of prediction mode.", _id);
|
||||
_prediction.frame = GameInput::NullFrame;
|
||||
} else {
|
||||
_prediction.frame++;
|
||||
|
@ -269,7 +269,7 @@ InputQueue::AddDelayedInputToQueue(GameInput &input, int frame_number)
|
|||
int
|
||||
InputQueue::AdvanceQueueHead(int frame)
|
||||
{
|
||||
Log("advancing queue head to frame %d.\n", frame);
|
||||
Log("input q%d | advancing queue head to frame %d.", _id, frame);
|
||||
|
||||
int expected_frame = _first_frame ? 0 : _inputs[PREVIOUS_FRAME(_head)].frame + 1;
|
||||
|
||||
|
@ -281,7 +281,7 @@ InputQueue::AdvanceQueueHead(int frame)
|
|||
* time we shoved a frame into the system. In this case, there's
|
||||
* no room on the queue. Toss it.
|
||||
*/
|
||||
Log("Dropping input frame %d (expected next frame to be %d).\n",
|
||||
Log("input q%d | Dropping input frame %d (expected next frame to be %d).", _id,
|
||||
frame, expected_frame);
|
||||
return GameInput::NullFrame;
|
||||
}
|
||||
|
@ -293,7 +293,7 @@ InputQueue::AdvanceQueueHead(int frame)
|
|||
* last frame in the queue several times in order to fill the space
|
||||
* left.
|
||||
*/
|
||||
Log("Adding padding frame %d to account for change in frame delay.\n",
|
||||
Log("input q%d | Adding padding frame %d to account for change in frame delay.", _id,
|
||||
expected_frame);
|
||||
GameInput &last_frame = _inputs[PREVIOUS_FRAME(_head)];
|
||||
AddDelayedInputToQueue(last_frame, expected_frame);
|
||||
|
@ -303,19 +303,3 @@ InputQueue::AdvanceQueueHead(int frame)
|
|||
ASSERT(frame == 0 || frame == _inputs[PREVIOUS_FRAME(_head)].frame + 1);
|
||||
return frame;
|
||||
}
|
||||
|
||||
|
||||
void
|
||||
InputQueue::Log(const char *fmt, ...)
|
||||
{
|
||||
char buf[1024];
|
||||
size_t offset;
|
||||
va_list args;
|
||||
|
||||
offset = snprintf(buf, ARRAY_SIZE(buf), "input q%d | ", _id);
|
||||
va_start(args, fmt);
|
||||
vsnprintf(buf + offset, ARRAY_SIZE(buf) - offset - 1, fmt, args);
|
||||
buf[ARRAY_SIZE(buf)-1] = '\0';
|
||||
::Log(buf);
|
||||
va_end(args);
|
||||
}
|
||||
|
|
|
@ -34,7 +34,6 @@ public:
|
|||
protected:
|
||||
int AdvanceQueueHead(int frame);
|
||||
void AddDelayedInputToQueue(GameInput &input, int i);
|
||||
void Log(const char *fmt, ...);
|
||||
|
||||
protected:
|
||||
int _id;
|
||||
|
|
|
@ -1,31 +0,0 @@
|
|||
/* -----------------------------------------------------------------------
|
||||
* GGPO.net (http://ggpo.net) - Copyright 2009 GroundStorm Studios, LLC.
|
||||
*
|
||||
* Use of this software is governed by the MIT license that can be found
|
||||
* in the LICENSE file.
|
||||
*/
|
||||
|
||||
#include "ggpo_types.h"
|
||||
#include "log/Log.h"
|
||||
#include "log/LogManager.h"
|
||||
#include <string>
|
||||
|
||||
void Log(const char *fmt, ...)
|
||||
{
|
||||
va_list args;
|
||||
va_start(args, fmt);
|
||||
Logv(fmt, args);
|
||||
va_end(args);
|
||||
}
|
||||
|
||||
void Logv(const char* fmt, va_list args)
|
||||
{
|
||||
std::string copy;
|
||||
if (fmt[strlen(fmt) - 1] == '\n') {
|
||||
copy = fmt;
|
||||
copy.pop_back();
|
||||
fmt = copy.c_str();
|
||||
}
|
||||
if (LogManager::GetInstance())
|
||||
LogManager::GetInstance()->Log(LogTypes::LDEBUG, LogTypes::NETWORK, __FILE__, __LINE__, fmt, args);
|
||||
}
|
|
@ -1,14 +0,0 @@
|
|||
/* -----------------------------------------------------------------------
|
||||
* GGPO.net (http://ggpo.net) - Copyright 2009 GroundStorm Studios, LLC.
|
||||
*
|
||||
* Use of this software is governed by the MIT license that can be found
|
||||
* in the LICENSE file.
|
||||
*/
|
||||
|
||||
#ifndef _LOG_H
|
||||
#define _LOG_H
|
||||
|
||||
extern void Log(const char *fmt, ...);
|
||||
extern void Logv(const char *fmt, va_list list);
|
||||
|
||||
#endif
|
|
@ -23,22 +23,6 @@ struct Init
|
|||
};
|
||||
static Init init;
|
||||
|
||||
void
|
||||
ggpo_log(GGPOSession *ggpo, const char *fmt, ...)
|
||||
{
|
||||
va_list args;
|
||||
va_start(args, fmt);
|
||||
ggpo_logv(ggpo, fmt, args);
|
||||
va_end(args);
|
||||
}
|
||||
|
||||
void
|
||||
ggpo_logv(GGPOSession *ggpo, const char *fmt, va_list args)
|
||||
{
|
||||
if (ggpo)
|
||||
ggpo->Logv(fmt, args);
|
||||
}
|
||||
|
||||
GGPOErrorCode
|
||||
ggpo_start_session(GGPOSession **session,
|
||||
GGPOSessionCallbacks *cb,
|
||||
|
@ -59,7 +43,7 @@ ggpo_start_session(GGPOSession **session,
|
|||
verification_size);
|
||||
return GGPO_OK;
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_start_session: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_start_session: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -74,7 +58,7 @@ ggpo_add_player(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->AddPlayer(player, handle);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_add_player: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_add_player: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -93,7 +77,7 @@ ggpo_start_synctest(GGPOSession **ggpo,
|
|||
*ggpo = (GGPOSession *)new SyncTestBackend(cb, game, frames, num_players);
|
||||
return GGPO_OK;
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_start_synctest: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_start_synctest: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -108,7 +92,7 @@ ggpo_set_frame_delay(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->SetFrameDelay(player, frame_delay);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_set_frame_delay: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_set_frame_delay: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -121,7 +105,7 @@ ggpo_idle(GGPOSession *ggpo, int timeout)
|
|||
try {
|
||||
return ggpo->DoPoll(timeout);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_idle: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_idle: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -137,7 +121,7 @@ ggpo_add_local_input(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->AddLocalInput(player, values, size);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_add_local_input: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_add_local_input: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -153,7 +137,7 @@ ggpo_synchronize_input(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->SyncInput(values, size, disconnect_flags);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_synchronize_input: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_synchronize_input: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -166,7 +150,7 @@ GGPOErrorCode ggpo_disconnect_player(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->DisconnectPlayer(player);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_disconnect_player: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_disconnect_player: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -179,7 +163,7 @@ ggpo_advance_frame(GGPOSession *ggpo)
|
|||
try {
|
||||
return ggpo->IncrementFrame();
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_advance_frame: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_advance_frame: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -194,7 +178,7 @@ ggpo_get_network_stats(GGPOSession *ggpo,
|
|||
try {
|
||||
return ggpo->GetNetworkStats(stats, player);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_get_network_stats: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_get_network_stats: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -218,7 +202,7 @@ ggpo_set_disconnect_timeout(GGPOSession *ggpo, int timeout)
|
|||
try {
|
||||
return ggpo->SetDisconnectTimeout(timeout);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_set_disconnect_timeout: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_set_disconnect_timeout: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -231,7 +215,7 @@ ggpo_set_disconnect_notify_start(GGPOSession *ggpo, int timeout)
|
|||
try {
|
||||
return ggpo->SetDisconnectNotifyStart(timeout);
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_set_disconnect_notify_start: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_set_disconnect_notify_start: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
@ -259,7 +243,7 @@ GGPOErrorCode ggpo_start_spectating(GGPOSession **session,
|
|||
verification_size);
|
||||
return GGPO_OK;
|
||||
} catch (const GGPOException& e) {
|
||||
Log("GGPOException in ggpo_start_spectating: %s", e.what());
|
||||
ERROR_LOG(NETWORK, "GGPOException in ggpo_start_spectating: %s", e.what());
|
||||
return e.ggpoError;
|
||||
}
|
||||
}
|
||||
|
|
|
@ -34,7 +34,7 @@ CreateSocket(uint16 bind_port, int retries)
|
|||
for (port = bind_port; port <= bind_port + retries; port++) {
|
||||
sin.sin_port = htons(port);
|
||||
if (bind(s, (sockaddr *)&sin, sizeof sin) == 0) {
|
||||
Log("Udp bound to port: %d.\n", port);
|
||||
Log("Udp bound to port: %d.", port);
|
||||
return s;
|
||||
}
|
||||
}
|
||||
|
@ -62,7 +62,7 @@ Udp::Init(uint16 port, Poll *poll, Callbacks *callbacks)
|
|||
_callbacks = callbacks;
|
||||
poll->RegisterLoop(this);
|
||||
|
||||
Log("binding udp socket to port %d.\n", port);
|
||||
Log("binding udp socket to port %d.", port);
|
||||
_socket = CreateSocket(port, 0);
|
||||
if (_socket == INVALID_SOCKET)
|
||||
throw GGPOException("Socket creation or bind failed", GGPO_ERRORCODE_NETWORK_ERROR);
|
||||
|
@ -76,11 +76,11 @@ Udp::SendTo(char *buffer, int len, int flags, struct sockaddr *dst, int destlen)
|
|||
int res = sendto(_socket, buffer, len, flags, dst, destlen);
|
||||
if (res == SOCKET_ERROR) {
|
||||
int err = WSAGetLastError();
|
||||
Log("unknown error in sendto (erro: %d wsaerr: %d).\n", res, err);
|
||||
Log("unknown error in sendto (erro: %d wsaerr: %d).", res, err);
|
||||
ASSERT(false && "Unknown error in sendto");
|
||||
}
|
||||
char dst_ip[1024];
|
||||
Log("sent packet length %d to %s:%d (ret:%d).\n", len, inet_ntop(AF_INET, (void *)&to->sin_addr, dst_ip, ARRAY_SIZE(dst_ip)), ntohs(to->sin_port), res);
|
||||
Log("sent packet length %d to %s:%d (ret:%d).", len, inet_ntop(AF_INET, (void *)&to->sin_addr, dst_ip, ARRAY_SIZE(dst_ip)), ntohs(to->sin_port), res);
|
||||
}
|
||||
|
||||
bool
|
||||
|
@ -99,32 +99,15 @@ Udp::OnLoopPoll(void *cookie)
|
|||
if (len == -1) {
|
||||
int error = WSAGetLastError();
|
||||
if (error != WSAEWOULDBLOCK) {
|
||||
Log("recvfrom WSAGetLastError returned %d (%x).\n", error, error);
|
||||
Log("recvfrom WSAGetLastError returned %d (%x).", error, error);
|
||||
}
|
||||
break;
|
||||
} else if (len > 0) {
|
||||
char src_ip[1024];
|
||||
Log("recvfrom returned (len:%d from:%s:%d).\n", len, inet_ntop(AF_INET, (void*)&recv_addr.sin_addr, src_ip, ARRAY_SIZE(src_ip)), ntohs(recv_addr.sin_port) );
|
||||
Log("recvfrom returned (len:%d from:%s:%d).", len, inet_ntop(AF_INET, (void*)&recv_addr.sin_addr, src_ip, ARRAY_SIZE(src_ip)), ntohs(recv_addr.sin_port) );
|
||||
UdpMsg *msg = (UdpMsg *)recv_buf;
|
||||
_callbacks->OnMsg(recv_addr, msg, len);
|
||||
}
|
||||
}
|
||||
return true;
|
||||
}
|
||||
|
||||
|
||||
void
|
||||
Udp::Log(const char *fmt, ...)
|
||||
{
|
||||
char buf[1024];
|
||||
size_t offset;
|
||||
va_list args;
|
||||
|
||||
strcpy(buf, "udp | ");
|
||||
offset = strlen(buf);
|
||||
va_start(args, fmt);
|
||||
vsnprintf(buf + offset, ARRAY_SIZE(buf) - offset - 1, fmt, args);
|
||||
buf[ARRAY_SIZE(buf)-1] = '\0';
|
||||
::Log(buf);
|
||||
va_end(args);
|
||||
}
|
||||
|
|
|
@ -31,11 +31,6 @@ public:
|
|||
virtual void OnMsg(sockaddr_in &from, UdpMsg *msg, int len) = 0;
|
||||
};
|
||||
|
||||
|
||||
protected:
|
||||
void Log(const char *fmt, ...);
|
||||
|
||||
public:
|
||||
Udp();
|
||||
|
||||
void Init(uint16 port, Poll *p, Callbacks *callbacks);
|
||||
|
|
|
@ -197,7 +197,7 @@ UdpProtocol::OnLoopPoll(void *cookie)
|
|||
case Syncing:
|
||||
next_interval = (_state.sync.roundtrips_remaining == NUM_SYNC_PACKETS) ? SYNC_FIRST_RETRY_INTERVAL : SYNC_RETRY_INTERVAL;
|
||||
if (_last_send_time && _last_send_time + next_interval < now && _peer_addr.sin_addr.s_addr != 0) {
|
||||
Log("No luck syncing after %d ms... Re-queueing sync packet.\n", next_interval);
|
||||
Log("udpproto%d | No luck syncing after %d ms... Re-queueing sync packet.", _queue, next_interval);
|
||||
SendSyncRequest();
|
||||
}
|
||||
break;
|
||||
|
@ -205,7 +205,7 @@ UdpProtocol::OnLoopPoll(void *cookie)
|
|||
case Running:
|
||||
// xxx: rig all this up with a timer wrapper
|
||||
if (!_state.running.last_input_packet_recv_time || _state.running.last_input_packet_recv_time + RUNNING_RETRY_INTERVAL < now) {
|
||||
Log("Haven't exchanged packets in a while (last received:%d last sent:%d). Resending.\n", _last_received_input.frame, _last_sent_input.frame);
|
||||
Log("udpproto%d | Haven't exchanged packets in a while (last received:%d last sent:%d). Resending.", _queue, _last_received_input.frame, _last_sent_input.frame);
|
||||
SendPendingOutput();
|
||||
_state.running.last_input_packet_recv_time = now;
|
||||
}
|
||||
|
@ -224,13 +224,13 @@ UdpProtocol::OnLoopPoll(void *cookie)
|
|||
}
|
||||
|
||||
if (_last_send_time && _last_send_time + KEEP_ALIVE_INTERVAL < now) {
|
||||
Log("Sending keep alive packet\n");
|
||||
Log("udpproto%d | Sending keep alive packet", _queue);
|
||||
SendMsg(new UdpMsg(UdpMsg::KeepAlive));
|
||||
}
|
||||
|
||||
if (_disconnect_timeout && _disconnect_notify_start &&
|
||||
!_disconnect_notify_sent && (_last_recv_time + _disconnect_notify_start < now)) {
|
||||
Log("Endpoint has stopped receiving packets for %d ms. Sending notification.\n", _disconnect_notify_start);
|
||||
Log("udpproto%d | Endpoint has stopped receiving packets for %d ms. Sending notification.", _queue, _disconnect_notify_start);
|
||||
Event e(Event::NetworkInterrupted);
|
||||
e.u.network_interrupted.disconnect_timeout = _disconnect_timeout - _disconnect_notify_start;
|
||||
QueueEvent(e);
|
||||
|
@ -239,7 +239,7 @@ UdpProtocol::OnLoopPoll(void *cookie)
|
|||
|
||||
if (_disconnect_timeout && (_last_recv_time + _disconnect_timeout < now)) {
|
||||
if (!_disconnect_event_sent) {
|
||||
Log("Endpoint has stopped receiving packets for %d ms. Disconnecting.\n", _disconnect_timeout);
|
||||
Log("udpproto%d | Endpoint has stopped receiving packets for %d ms. Disconnecting.", _queue, _disconnect_timeout);
|
||||
QueueEvent(Event(Event::Disconnected));
|
||||
_disconnect_event_sent = true;
|
||||
}
|
||||
|
@ -248,7 +248,7 @@ UdpProtocol::OnLoopPoll(void *cookie)
|
|||
|
||||
case Disconnected:
|
||||
if (_shutdown_timeout < now) {
|
||||
Log("Shutting down udp connection.\n");
|
||||
Log("udpproto%d | Shutting down udp connection.", _queue);
|
||||
_udp = NULL;
|
||||
_shutdown_timeout = 0;
|
||||
}
|
||||
|
@ -345,9 +345,9 @@ UdpProtocol::OnMsg(UdpMsg *msg, int len)
|
|||
|
||||
// filter out out-of-order packets
|
||||
uint16 skipped = (uint16)((int)seq - (int)_next_recv_seq);
|
||||
// Log("checking sequence number -> next - seq : %d - %d = %d\n", seq, _next_recv_seq, skipped);
|
||||
// Log("udpproto%d | checking sequence number -> next - seq : %d - %d = %d", _queue, seq, _next_recv_seq, skipped);
|
||||
if (skipped > MAX_SEQ_DISTANCE) {
|
||||
Log("dropping out of order packet (seq: %d, last seq:%d)\n", seq, _next_recv_seq);
|
||||
Log("udpproto%d | dropping out of order packet (seq: %d, last seq:%d)", _queue, seq, _next_recv_seq);
|
||||
return;
|
||||
}
|
||||
}
|
||||
|
@ -384,9 +384,9 @@ UdpProtocol::UpdateNetworkStats(void)
|
|||
|
||||
_kbps_sent = int(Bps / 1024);
|
||||
|
||||
Log("Network Stats -- Bandwidth: %.2f KBps Packets Sent: %5d (%.2f pps) "
|
||||
"KB Sent: %.2f UDP Overhead: %.2f %%.\n",
|
||||
_kbps_sent,
|
||||
Log("udpproto%d | Network Stats -- Bandwidth: %.2f KBps Packets Sent: %5d (%.2f pps) "
|
||||
"KB Sent: %.2f UDP Overhead: %.2f %%.", _queue,
|
||||
(float)_kbps_sent,
|
||||
_packets_sent,
|
||||
(float)_packets_sent * 1000 / (now - _stats_start_time),
|
||||
total_bytes_sent / 1024.0,
|
||||
|
@ -419,51 +419,35 @@ UdpProtocol::GetPeerConnectStatus(int id, int *frame)
|
|||
return !_peer_connect_status[id].disconnected;
|
||||
}
|
||||
|
||||
void
|
||||
UdpProtocol::Log(const char *fmt, ...)
|
||||
{
|
||||
char buf[1024];
|
||||
size_t offset;
|
||||
va_list args;
|
||||
|
||||
snprintf(buf, ARRAY_SIZE(buf), "udpproto%d | ", _queue);
|
||||
offset = strlen(buf);
|
||||
va_start(args, fmt);
|
||||
vsnprintf(buf + offset, ARRAY_SIZE(buf) - offset - 1, fmt, args);
|
||||
buf[ARRAY_SIZE(buf)-1] = '\0';
|
||||
::Log(buf);
|
||||
va_end(args);
|
||||
}
|
||||
|
||||
void
|
||||
UdpProtocol::LogMsg(const char *prefix, UdpMsg *msg)
|
||||
{
|
||||
switch (msg->hdr.type) {
|
||||
case UdpMsg::SyncRequest:
|
||||
Log("%s sync-request (%d).\n", prefix,
|
||||
Log("udpproto%d | %s sync-request (%d).", _queue, prefix,
|
||||
msg->u.sync_request.random_request);
|
||||
break;
|
||||
case UdpMsg::SyncReply:
|
||||
Log("%s sync-reply (%d).\n", prefix,
|
||||
Log("udpproto%d | %s sync-reply (%d).", _queue, prefix,
|
||||
msg->u.sync_reply.random_reply);
|
||||
break;
|
||||
case UdpMsg::QualityReport:
|
||||
Log("%s quality report.\n", prefix);
|
||||
Log("udpproto%d | %s quality report.", _queue, prefix);
|
||||
break;
|
||||
case UdpMsg::QualityReply:
|
||||
Log("%s quality reply.\n", prefix);
|
||||
Log("udpproto%d | %s quality reply.", _queue, prefix);
|
||||
break;
|
||||
case UdpMsg::KeepAlive:
|
||||
Log("%s keep alive.\n", prefix);
|
||||
Log("udpproto%d | %s keep alive.", _queue, prefix);
|
||||
break;
|
||||
case UdpMsg::Input:
|
||||
Log("%s game-compressed-input %d (+ %d bits).\n", prefix, msg->u.input.start_frame, msg->u.input.num_bits);
|
||||
Log("udpproto%d | %s game-compressed-input %d (+ %d bits).", _queue, prefix, msg->u.input.start_frame, msg->u.input.num_bits);
|
||||
break;
|
||||
case UdpMsg::InputAck:
|
||||
Log("%s input ack.\n", prefix);
|
||||
Log("udpproto%d | %s input ack.", _queue, prefix);
|
||||
break;
|
||||
case UdpMsg::AppData:
|
||||
Log("%s app data (%d bytes).\n", prefix, msg->u.app_data.size);
|
||||
Log("udpproto%d | %s app data (%d bytes).", _queue, prefix, msg->u.app_data.size);
|
||||
break;
|
||||
default:
|
||||
ASSERT(false && "Unknown UdpMsg type.");
|
||||
|
@ -474,7 +458,7 @@ void
|
|||
UdpProtocol::LogEvent(const char *prefix, const UdpProtocol::Event &evt)
|
||||
{
|
||||
if (evt.type == UdpProtocol::Event::Synchronzied)
|
||||
Log("%s (event: Synchronzied).\n", prefix);
|
||||
Log("udpproto%d | %s (event: Synchronized).", _queue, prefix);
|
||||
}
|
||||
|
||||
bool
|
||||
|
@ -488,7 +472,7 @@ bool
|
|||
UdpProtocol::OnSyncRequest(UdpMsg *msg, int len)
|
||||
{
|
||||
if (_remote_magic_number != 0 && msg->hdr.magic != _remote_magic_number) {
|
||||
Log("Ignoring sync request from unknown endpoint (%d != %d).\n",
|
||||
Log("udpproto%d | Ignoring sync request from unknown endpoint (%d != %d).", _queue,
|
||||
msg->hdr.magic, _remote_magic_number);
|
||||
return false;
|
||||
}
|
||||
|
@ -500,14 +484,14 @@ UdpProtocol::OnSyncRequest(UdpMsg *msg, int len)
|
|||
if (msgVerifSize != (int)verification.size()
|
||||
|| (msgVerifSize != 0 && memcmp(&msg->u.sync_request.verification[0], &verification[0], msgVerifSize)))
|
||||
{
|
||||
Log("Verification mismatch: size received %d expected %d", msgVerifSize, (int)verification.size());
|
||||
Log("udpproto%d | Verification mismatch: size received %d expected %d", _queue, msgVerifSize, (int)verification.size());
|
||||
reply->u.sync_reply.verification_failure = 1;
|
||||
SendMsg(reply);
|
||||
throw GGPOException("Verification mismatch", GGPO_ERRORCODE_VERIFICATION_ERROR);
|
||||
}
|
||||
// FIXME
|
||||
if (_state.sync.roundtrips_remaining == NUM_SYNC_PACKETS && msg->hdr.sequence_number == 0) {
|
||||
Log("Sync request 0 received... Re-queueing sync packet.\n");
|
||||
Log("udpproto%d | Sync request 0 received... Re-queueing sync packet.", _queue);
|
||||
SendSyncRequest();
|
||||
}
|
||||
|
||||
|
@ -521,12 +505,12 @@ bool
|
|||
UdpProtocol::OnSyncReply(UdpMsg *msg, int len)
|
||||
{
|
||||
if (_current_state != Syncing) {
|
||||
Log("Ignoring SyncReply while not synching.\n");
|
||||
Log("udpproto%d | Ignoring SyncReply while not synching.", _queue);
|
||||
return msg->hdr.magic == _remote_magic_number;
|
||||
}
|
||||
|
||||
if (msg->u.sync_reply.random_reply != _state.sync.random) {
|
||||
Log("sync reply %d != %d. Keep looking...\n",
|
||||
Log("udpproto%d | sync reply %d != %d. Keep looking...", _queue,
|
||||
msg->u.sync_reply.random_reply, _state.sync.random);
|
||||
return false;
|
||||
}
|
||||
|
@ -538,9 +522,9 @@ UdpProtocol::OnSyncReply(UdpMsg *msg, int len)
|
|||
_connected = true;
|
||||
}
|
||||
|
||||
Log("Checking sync state (%d round trips remaining).\n", _state.sync.roundtrips_remaining);
|
||||
Log("udpproto%d | Checking sync state (%d round trips remaining).", _queue, _state.sync.roundtrips_remaining);
|
||||
if (--_state.sync.roundtrips_remaining == 0) {
|
||||
Log("Synchronized!\n");
|
||||
Log("udpproto%d | Synchronized!", _queue);
|
||||
QueueEvent(UdpProtocol::Event(UdpProtocol::Event::Synchronzied));
|
||||
_current_state = Running;
|
||||
_last_received_input.frame = -1;
|
||||
|
@ -564,7 +548,7 @@ UdpProtocol::OnInput(UdpMsg *msg, int len)
|
|||
bool disconnect_requested = msg->u.input.disconnect_requested;
|
||||
if (disconnect_requested) {
|
||||
if (_current_state != Disconnected && !_disconnect_event_sent) {
|
||||
Log("Disconnecting endpoint on remote request.\n");
|
||||
Log("udpproto%d | Disconnecting endpoint on remote request.", _queue);
|
||||
QueueEvent(Event(Event::Disconnected));
|
||||
_disconnect_event_sent = true;
|
||||
}
|
||||
|
@ -629,20 +613,21 @@ UdpProtocol::OnInput(UdpMsg *msg, int len)
|
|||
_last_received_input.frame = currentFrame;
|
||||
|
||||
/*
|
||||
* Send the event to the emualtor
|
||||
* Send the event to the emulator
|
||||
*/
|
||||
UdpProtocol::Event evt(UdpProtocol::Event::Input);
|
||||
evt.u.input.input = _last_received_input;
|
||||
|
||||
_last_received_input.desc(desc, ARRAY_SIZE(desc));
|
||||
if (LogTypes::LDEBUG <= MAX_LOGLEVEL)
|
||||
_last_received_input.desc(desc, ARRAY_SIZE(desc));
|
||||
|
||||
_state.running.last_input_packet_recv_time = GGPOPlatform::GetCurrentTimeMS();
|
||||
|
||||
Log("Sending frame %d to emu queue %d (%s).\n", _last_received_input.frame, _queue, desc);
|
||||
Log("udpproto%d | Sending frame %d to emu queue %d (%s).", _queue, _last_received_input.frame, _queue, desc);
|
||||
QueueEvent(evt);
|
||||
|
||||
} else {
|
||||
Log("Skipping past frame:(%d) current is %d.\n", currentFrame, _last_received_input.frame);
|
||||
Log("udpproto%d | Skipping past frame:(%d) current is %d.", _queue, currentFrame, _last_received_input.frame);
|
||||
}
|
||||
|
||||
/*
|
||||
|
@ -657,7 +642,7 @@ UdpProtocol::OnInput(UdpMsg *msg, int len)
|
|||
* Get rid of our buffered input
|
||||
*/
|
||||
while (_pending_output.size() && _pending_output.front().frame < msg->u.input.ack_frame) {
|
||||
Log("Throwing away pending output frame %d\n", _pending_output.front().frame);
|
||||
Log("udpproto%d | Throwing away pending output frame %d", _queue, _pending_output.front().frame);
|
||||
_last_acked_input = _pending_output.front();
|
||||
_pending_output.pop();
|
||||
}
|
||||
|
@ -672,7 +657,7 @@ UdpProtocol::OnInputAck(UdpMsg *msg, int len)
|
|||
* Get rid of our buffered input
|
||||
*/
|
||||
while (_pending_output.size() && _pending_output.front().frame < msg->u.input_ack.ack_frame) {
|
||||
Log("Throwing away pending output frame %d\n", _pending_output.front().frame);
|
||||
Log("udpproto%d | Throwing away pending output frame %d", _queue, _pending_output.front().frame);
|
||||
_last_acked_input = _pending_output.front();
|
||||
_pending_output.pop();
|
||||
}
|
||||
|
@ -770,7 +755,7 @@ UdpProtocol::PumpSendQueue()
|
|||
}
|
||||
if (_oop_percent && !_oo_packet.msg && ((rand() % 100) < _oop_percent)) {
|
||||
int delay = rand() % (_send_latency * 10 + 1000);
|
||||
Log("creating rogue oop (seq: %d delay: %d)\n", entry.msg->hdr.sequence_number, delay);
|
||||
Log("udpproto%d | creating rogue oop (seq: %d delay: %d)", _queue, entry.msg->hdr.sequence_number, delay);
|
||||
_oo_packet.send_time = GGPOPlatform::GetCurrentTimeMS() + delay;
|
||||
_oo_packet.msg = entry.msg;
|
||||
_oo_packet.dest_addr = entry.dest_addr;
|
||||
|
@ -785,7 +770,7 @@ UdpProtocol::PumpSendQueue()
|
|||
_send_queue.pop();
|
||||
}
|
||||
if (_oo_packet.msg && _oo_packet.send_time < (int)GGPOPlatform::GetCurrentTimeMS()) {
|
||||
Log("sending rogue oop!");
|
||||
Log("udpproto%d | sending rogue oop!", _queue);
|
||||
_udp->SendTo((char *)_oo_packet.msg, _oo_packet.msg->PacketSize(), 0,
|
||||
(struct sockaddr *)&_oo_packet.dest_addr, sizeof _oo_packet.dest_addr);
|
||||
|
||||
|
|
|
@ -119,7 +119,6 @@ protected:
|
|||
void UpdateNetworkStats(void);
|
||||
void QueueEvent(const UdpProtocol::Event &evt);
|
||||
void ClearSendQueue(void);
|
||||
void Log(const char *fmt, ...);
|
||||
void LogMsg(const char *prefix, UdpMsg *msg);
|
||||
void LogEvent(const char *prefix, const UdpProtocol::Event &evt);
|
||||
void SendSyncRequest();
|
||||
|
|
|
@ -59,7 +59,7 @@ Sync::AddLocalInput(int queue, GameInput &input)
|
|||
{
|
||||
int frames_behind = _framecount - _last_confirmed_frame;
|
||||
if (_framecount >= _max_prediction_frames && frames_behind >= _max_prediction_frames) {
|
||||
Log("Rejecting input from emulator: reached prediction barrier.\n");
|
||||
Log("Rejecting input from emulator: reached prediction barrier.");
|
||||
return false;
|
||||
}
|
||||
|
||||
|
@ -67,7 +67,7 @@ Sync::AddLocalInput(int queue, GameInput &input)
|
|||
SaveCurrentFrame();
|
||||
}
|
||||
|
||||
Log("Sending undelayed local frame %d to queue %d.\n", _framecount, queue);
|
||||
Log("Sending undelayed local frame %d to queue %d.", _framecount, queue);
|
||||
input.frame = _framecount;
|
||||
_input_queues[queue].AddInput(input);
|
||||
|
||||
|
@ -146,7 +146,7 @@ Sync::AdjustSimulation(int seek_to)
|
|||
int framecount = _framecount;
|
||||
int count = _framecount - seek_to;
|
||||
|
||||
Log("Catching up\n");
|
||||
Log("Catching up");
|
||||
_rollingback = true;
|
||||
|
||||
/*
|
||||
|
@ -167,7 +167,7 @@ Sync::AdjustSimulation(int seek_to)
|
|||
|
||||
_rollingback = false;
|
||||
|
||||
Log("---\n");
|
||||
Log("---");
|
||||
}
|
||||
|
||||
void
|
||||
|
@ -175,7 +175,7 @@ Sync::LoadFrame(int frame)
|
|||
{
|
||||
// find the frame in question
|
||||
if (frame == _framecount) {
|
||||
Log("Skipping NOP.\n");
|
||||
Log("Skipping NOP.");
|
||||
return;
|
||||
}
|
||||
|
||||
|
@ -183,7 +183,7 @@ Sync::LoadFrame(int frame)
|
|||
_savedstate.head = FindSavedFrameIndex(frame);
|
||||
SavedFrame *state = _savedstate.frames + _savedstate.head;
|
||||
|
||||
Log("=== Loading frame info %d (size: %d checksum: %08x).\n",
|
||||
Log("=== Loading frame info %d (size: %d checksum: %08x).",
|
||||
state->frame, state->cbuf, state->checksum);
|
||||
|
||||
ASSERT(state->buf && state->cbuf);
|
||||
|
@ -210,7 +210,7 @@ Sync::SaveCurrentFrame()
|
|||
state->frame = _framecount;
|
||||
_callbacks.save_game_state(&state->buf, &state->cbuf, &state->checksum, state->frame);
|
||||
|
||||
Log("=== Saved frame info %d (size: %d checksum: %08x).\n", state->frame, state->cbuf, state->checksum);
|
||||
Log("=== Saved frame info %d (size: %d checksum: %08x).", state->frame, state->cbuf, state->checksum);
|
||||
_savedstate.head = (_savedstate.head + 1) % ARRAY_SIZE(_savedstate.frames);
|
||||
}
|
||||
|
||||
|
@ -259,7 +259,7 @@ Sync::CheckSimulationConsistency(int *seekTo)
|
|||
int first_incorrect = GameInput::NullFrame;
|
||||
for (int i = 0; i < _config.num_players; i++) {
|
||||
int incorrect = _input_queues[i].GetFirstIncorrectFrame();
|
||||
Log("considering incorrect frame %d reported by queue %d.\n", incorrect, i);
|
||||
Log("considering incorrect frame %d reported by queue %d.", incorrect, i);
|
||||
|
||||
if (incorrect != GameInput::NullFrame && (first_incorrect == GameInput::NullFrame || incorrect < first_incorrect)) {
|
||||
first_incorrect = incorrect;
|
||||
|
@ -267,7 +267,7 @@ Sync::CheckSimulationConsistency(int *seekTo)
|
|||
}
|
||||
|
||||
if (first_incorrect == GameInput::NullFrame) {
|
||||
Log("prediction ok. proceeding.\n");
|
||||
Log("prediction ok. proceeding.");
|
||||
return true;
|
||||
}
|
||||
*seekTo = first_incorrect;
|
||||
|
|
|
@ -59,7 +59,7 @@ TimeSync::recommend_frame_wait_duration(bool require_idle_input)
|
|||
// sleep for.
|
||||
int sleep_frames = (int)(((radvantage - advantage) / 2) + 0.5);
|
||||
|
||||
Log("iteration %d: sleep frames is %d\n", count, sleep_frames);
|
||||
Log("iteration %d: sleep frames is %d", count, sleep_frames);
|
||||
|
||||
// Some things just aren't worth correcting for. Make sure
|
||||
// the difference is relevant before proceeding.
|
||||
|
@ -74,7 +74,7 @@ TimeSync::recommend_frame_wait_duration(bool require_idle_input)
|
|||
if (require_idle_input) {
|
||||
for (size_t i = 1; i < ARRAY_SIZE(_last_inputs); i++) {
|
||||
if (!_last_inputs[i].equal(_last_inputs[0], true)) {
|
||||
Log("iteration %d: rejecting due to input stuff at position %d...!!!\n", count, i);
|
||||
Log("iteration %d: rejecting due to input stuff at position %d...!!!", count, (int)i);
|
||||
return 0;
|
||||
}
|
||||
}
|
||||
|
|
Loading…
Reference in New Issue