From d76dff8594415aaaa1b8bb617e9dd29453f9920f Mon Sep 17 00:00:00 2001 From: Flyinghead Date: Sat, 10 Dec 2022 13:06:31 +0100 Subject: [PATCH] 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. --- CMakeLists.txt | 2 - core/deps/ggpo/include/ggponet.h | 20 ----- core/deps/ggpo/lib/ggpo/backends/backend.h | 1 - core/deps/ggpo/lib/ggpo/backends/p2p.cpp | 38 ++++---- .../deps/ggpo/lib/ggpo/backends/spectator.cpp | 2 +- core/deps/ggpo/lib/ggpo/backends/synctest.cpp | 42 +-------- core/deps/ggpo/lib/ggpo/backends/synctest.h | 3 - core/deps/ggpo/lib/ggpo/game_input.cpp | 17 ++-- core/deps/ggpo/lib/ggpo/ggpo_types.h | 15 ++-- core/deps/ggpo/lib/ggpo/input_queue.cpp | 52 ++++------- core/deps/ggpo/lib/ggpo/input_queue.h | 1 - core/deps/ggpo/lib/ggpo/log.cpp | 31 ------- core/deps/ggpo/lib/ggpo/log.h | 14 --- core/deps/ggpo/lib/ggpo/main.cpp | 42 +++------ core/deps/ggpo/lib/ggpo/network/udp.cpp | 29 ++---- core/deps/ggpo/lib/ggpo/network/udp.h | 5 -- core/deps/ggpo/lib/ggpo/network/udp_proto.cpp | 89 ++++++++----------- core/deps/ggpo/lib/ggpo/network/udp_proto.h | 1 - core/deps/ggpo/lib/ggpo/sync.cpp | 18 ++-- core/deps/ggpo/lib/ggpo/timesync.cpp | 4 +- 20 files changed, 119 insertions(+), 307 deletions(-) delete mode 100644 core/deps/ggpo/lib/ggpo/log.cpp delete mode 100644 core/deps/ggpo/lib/ggpo/log.h diff --git a/CMakeLists.txt b/CMakeLists.txt index d9a0065f0..417e8ff6c 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -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 diff --git a/core/deps/ggpo/include/ggponet.h b/core/deps/ggpo/include/ggponet.h index 29eba49c1..9bf8552ec 100644 --- a/core/deps/ggpo/include/ggponet.h +++ b/core/deps/ggpo/include/ggponet.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 -- * diff --git a/core/deps/ggpo/lib/ggpo/backends/backend.h b/core/deps/ggpo/lib/ggpo/backends/backend.h index 39a176fbd..b8b0a3402 100644 --- a/core/deps/ggpo/lib/ggpo/backends/backend.h +++ b/core/deps/ggpo/lib/ggpo/backends/backend.h @@ -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; } diff --git a/core/deps/ggpo/lib/ggpo/backends/p2p.cpp b/core/deps/ggpo/lib/ggpo/backends/p2p.cpp index 57628da26..b47b131a5 100644 --- a/core/deps/ggpo/lib/ggpo/backends/p2p.cpp +++ b/core/deps/ggpo/lib/ggpo/backends/p2p.cpp @@ -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; diff --git a/core/deps/ggpo/lib/ggpo/backends/spectator.cpp b/core/deps/ggpo/lib/ggpo/backends/spectator.cpp index df65dd410..1e820de57 100644 --- a/core/deps/ggpo/lib/ggpo/backends/spectator.cpp +++ b/core/deps/ggpo/lib/ggpo/backends/spectator.cpp @@ -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(); diff --git a/core/deps/ggpo/lib/ggpo/backends/synctest.cpp b/core/deps/ggpo/lib/ggpo/backends/synctest.cpp index 10e5b3147..370266525 100644 --- a/core/deps/ggpo/lib/ggpo/backends/synctest.cpp +++ b/core/deps/ggpo/lib/ggpo/backends/synctest.cpp @@ -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) { diff --git a/core/deps/ggpo/lib/ggpo/backends/synctest.h b/core/deps/ggpo/lib/ggpo/backends/synctest.h index bd947517e..209a8d4ef 100644 --- a/core/deps/ggpo/lib/ggpo/backends/synctest.h +++ b/core/deps/ggpo/lib/ggpo/backends/synctest.h @@ -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: diff --git a/core/deps/ggpo/lib/ggpo/game_input.cpp b/core/deps/ggpo/lib/ggpo/game_input.cpp index a1d62dc37..7a380a6cb 100644 --- a/core/deps/ggpo/lib/ggpo/game_input.cpp +++ b/core/deps/ggpo/lib/ggpo/game_input.cpp @@ -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; } diff --git a/core/deps/ggpo/lib/ggpo/ggpo_types.h b/core/deps/ggpo/lib/ggpo/ggpo_types.h index 54abecdf5..44106ab13 100644 --- a/core/deps/ggpo/lib/ggpo/ggpo_types.h +++ b/core/deps/ggpo/lib/ggpo/ggpo_types.h @@ -40,6 +40,7 @@ typedef short int16; typedef int int32; #include "ggponet.h" +#include "log/Log.h" #include 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 diff --git a/core/deps/ggpo/lib/ggpo/input_queue.cpp b/core/deps/ggpo/lib/ggpo/input_queue.cpp index 3441ef70c..051c47e7d 100644 --- a/core/deps/ggpo/lib/ggpo/input_queue.cpp +++ b/core/deps/ggpo/lib/ggpo/input_queue.cpp @@ -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); -} diff --git a/core/deps/ggpo/lib/ggpo/input_queue.h b/core/deps/ggpo/lib/ggpo/input_queue.h index 460a50168..62f86daf2 100644 --- a/core/deps/ggpo/lib/ggpo/input_queue.h +++ b/core/deps/ggpo/lib/ggpo/input_queue.h @@ -34,7 +34,6 @@ public: protected: int AdvanceQueueHead(int frame); void AddDelayedInputToQueue(GameInput &input, int i); - void Log(const char *fmt, ...); protected: int _id; diff --git a/core/deps/ggpo/lib/ggpo/log.cpp b/core/deps/ggpo/lib/ggpo/log.cpp deleted file mode 100644 index b816a05f2..000000000 --- a/core/deps/ggpo/lib/ggpo/log.cpp +++ /dev/null @@ -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 - -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); -} diff --git a/core/deps/ggpo/lib/ggpo/log.h b/core/deps/ggpo/lib/ggpo/log.h deleted file mode 100644 index 0096b2416..000000000 --- a/core/deps/ggpo/lib/ggpo/log.h +++ /dev/null @@ -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 diff --git a/core/deps/ggpo/lib/ggpo/main.cpp b/core/deps/ggpo/lib/ggpo/main.cpp index 694555c44..258f5f5dd 100644 --- a/core/deps/ggpo/lib/ggpo/main.cpp +++ b/core/deps/ggpo/lib/ggpo/main.cpp @@ -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; } } diff --git a/core/deps/ggpo/lib/ggpo/network/udp.cpp b/core/deps/ggpo/lib/ggpo/network/udp.cpp index 5b3686937..4b0ea8080 100644 --- a/core/deps/ggpo/lib/ggpo/network/udp.cpp +++ b/core/deps/ggpo/lib/ggpo/network/udp.cpp @@ -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); -} diff --git a/core/deps/ggpo/lib/ggpo/network/udp.h b/core/deps/ggpo/lib/ggpo/network/udp.h index 7af07d8c0..ade94c586 100644 --- a/core/deps/ggpo/lib/ggpo/network/udp.h +++ b/core/deps/ggpo/lib/ggpo/network/udp.h @@ -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); diff --git a/core/deps/ggpo/lib/ggpo/network/udp_proto.cpp b/core/deps/ggpo/lib/ggpo/network/udp_proto.cpp index 6f29dbb7e..2a9a5acec 100644 --- a/core/deps/ggpo/lib/ggpo/network/udp_proto.cpp +++ b/core/deps/ggpo/lib/ggpo/network/udp_proto.cpp @@ -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); diff --git a/core/deps/ggpo/lib/ggpo/network/udp_proto.h b/core/deps/ggpo/lib/ggpo/network/udp_proto.h index 00af4f8b2..a19e9f701 100644 --- a/core/deps/ggpo/lib/ggpo/network/udp_proto.h +++ b/core/deps/ggpo/lib/ggpo/network/udp_proto.h @@ -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(); diff --git a/core/deps/ggpo/lib/ggpo/sync.cpp b/core/deps/ggpo/lib/ggpo/sync.cpp index c133735c3..8670a14d2 100644 --- a/core/deps/ggpo/lib/ggpo/sync.cpp +++ b/core/deps/ggpo/lib/ggpo/sync.cpp @@ -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; diff --git a/core/deps/ggpo/lib/ggpo/timesync.cpp b/core/deps/ggpo/lib/ggpo/timesync.cpp index 5fd7722f0..df9e2cfe7 100644 --- a/core/deps/ggpo/lib/ggpo/timesync.cpp +++ b/core/deps/ggpo/lib/ggpo/timesync.cpp @@ -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; } }