Merge pull request #189 from TheUbMunster/fix-race-condition

Fix PINE waitUntilPineDataPresent race condition.

decompile/General/AltMods/OnlineCTR/global.h

@@ -141,6 +141,10 @@ struct OnlineCTR
 	char lastWindowsClientSync;
 
 	char desiredFPS;
+
+#ifdef PINE_DEBUG
+	int stateChangeCounter;
+#endif
 };
 
 STATIC_ASSERT2(sizeof(struct OnlineCTR) <= 0x400, "Size of OnlineCTR must be lte 1kb");

decompile/General/AltMods/OnlineCTR/hooks.c

@@ -167,8 +167,13 @@ void OnlineInit_Drivers(struct GameTracker* gGT)
 		#endif
 	}
 
-	if(gGT->levelID != 0x26)
+	if (gGT->levelID != 0x26)
+	{
 		octr->CurrState = GAME_WAIT_FOR_RACE;
+#ifdef PINE_DEBUG
+		printf("statechange %d GAME_WAIT_FOR_RACE 1: \n", octr->stateChangeCounter++);
+#endif
+	}
 }
 
 bool HasRaceEnded()
@@ -190,6 +195,9 @@ void OnlineEndOfRace()
 		(octr->CurrState < GAME_START_RACE)) { return; }
 
 	octr->CurrState = GAME_END_RACE;
+#ifdef PINE_DEBUG
+	printf("statechange %d GAME_END_RACE 2: \n", octr->stateChangeCounter++);
+#endif
 
 	static unsigned frameCounter = 0;
 	EndOfRace_Camera();

decompile/General/AltMods/OnlineCTR/states.c

@@ -126,11 +126,17 @@ void StatePS1_Lobby_AssignRole()
 	if(octr->DriverID == 0)
 	{
 		octr->CurrState = LOBBY_HOST_TRACK_PICK;
+#ifdef PINE_DEBUG
+		printf("statechange %d LOBBY_HOST_TRACK_PICK 3: \n", octr->stateChangeCounter++);
+#endif
 	}
 
 	else if (octr->DriverID > 0)
 	{
 		octr->CurrState = LOBBY_GUEST_TRACK_WAIT;
+#ifdef PINE_DEBUG
+		printf("statechange %d LOBBY_GUEST_TRACK_WAIT 4: \n", octr->stateChangeCounter++);
+#endif
 	}
 }
 

decompile/General/AltMods/OnlineCTR/thread.c

@@ -84,6 +84,32 @@ void ThreadFunc(struct Thread* t)
         octr->frames_unsynced = 0;
     }
 
+	//this debug info courtesy of ClaudioBo
+#ifdef PINE_DEBUG
+	static unsigned frameCounter = 0;
+	char frames_unsynced_str[12];
+	sprintf(frames_unsynced_str, "%d", octr->frames_unsynced);
+
+	if (octr->frames_unsynced >= 80) {
+		int color = frameCounter++ & FPS_DOUBLE(1) ? RED : WHITE;
+		char final_str[20];
+		sprintf(final_str, "WTF!!: %s/120", frames_unsynced_str);
+		DECOMP_DecalFont_DrawLine(final_str, 0x100, 200, FONT_BIG, JUSTIFY_CENTER | color);
+	}
+	else if (octr->frames_unsynced >= 60) {
+		DECOMP_DecalFont_DrawLine(frames_unsynced_str, 0x100, 200, FONT_BIG, JUSTIFY_CENTER | CORTEX_RED);
+	}
+	else if (octr->frames_unsynced >= 40) {
+		DECOMP_DecalFont_DrawLine(frames_unsynced_str, 0x100, 200, FONT_BIG, JUSTIFY_CENTER | ROO_ORANGE);
+	}
+	else if (octr->frames_unsynced >= 20) {
+		DECOMP_DecalFont_DrawLine(frames_unsynced_str, 0x100, 200, FONT_BIG, JUSTIFY_CENTER | PAPU_YELLOW);
+	}
+	else {
+		DECOMP_DecalFont_DrawLine(frames_unsynced_str, 0x100, 200, FONT_BIG, JUSTIFY_CENTER | WHITE);
+	}
+#endif
+
 	// close if client didn't update the game in DISCONNECT_AT_UNSYNCED_FRAMES
 	int boolCloseClient = (octr->frames_unsynced > DISCONNECT_AT_UNSYNCED_FRAMES);
 
@@ -97,6 +123,9 @@ void ThreadFunc(struct Thread* t)
 			// if closed==1, go to 0 ("please open client")
 			// if closed==0, go to 1 (server select)
 			octr->CurrState = !boolCloseClient;
+#ifdef PINE_DEBUG
+			printf("statechange %d yesno open client/server select 5: \n", octr->stateChangeCounter++);
+#endif
 
 			octr->serverLockIn1 = 0;
 			octr->serverLockIn2 = 0;
@@ -109,6 +138,9 @@ void ThreadFunc(struct Thread* t)
 		// if closed==1, go to 0 ("please open client")
 		// if closed==0, go to 1 (server select)
 		octr->CurrState = !boolCloseClient;
+#ifdef PINE_DEBUG
+		printf("statechange %d yesno open client/server select 6: \n", octr->stateChangeCounter++);
+#endif
 
 		// stop music,
 		// stop "most FX", let menu FX ring

include/common.h

@@ -28,6 +28,7 @@
 #define USE_RAMEX
 #define USE_BIGQUEUE
 #define USE_HIGH1P
+//#define PINE_DEBUG //enable this for logging of CurrState change on game and client.
 #endif
 
 #ifdef USE_60FPS

mods/Windows/OnlineCTR/Network_PC/Client/CL_main.cpp

@@ -137,12 +137,18 @@ void ProcessReceiveEvent(ENetPacket* packet)
 			if (r->version != VERSION)
 			{
 				octr.get()->CurrState = LAUNCH_ERROR;
+#ifdef PINE_DEBUG
+				printf("statechange %d LAUNCH_ERROR 7: version mismatch\n", octr.get()->stateChangeCounter++);
+#endif
 				return;
 			}
 
 			if (octr.get()->ver_psx != VERSION)
 			{
 				octr.get()->CurrState = LAUNCH_ERROR;
+#ifdef PINE_DEBUG
+				printf("statechange %d LAUNCH_ERROR 8: version mismatch\n", octr.get()->stateChangeCounter++);
+#endif
 				return;
 			}
 
@@ -240,6 +246,9 @@ void ProcessReceiveEvent(ENetPacket* packet)
 
 			// choose to get host menu or guest menu
 			octr.get()->CurrState = LOBBY_ASSIGN_ROLE;
+#ifdef PINE_DEBUG
+			printf("statechange %d LOBBY_ASSIGN_ROLE 9: new client\n", octr.get()->stateChangeCounter++);
+#endif
 			break;
 		}
 
@@ -290,6 +299,9 @@ void ProcessReceiveEvent(ENetPacket* packet)
 
 			octr.get()->levelID = r->trackID;
 			octr.get()->CurrState = LOBBY_CHARACTER_PICK;
+#ifdef PINE_DEBUG
+			printf("statechange %d LOBBY_CHARACTER_PICK 10: track was selected\n", octr.get()->stateChangeCounter++);
+#endif
 			break;
 		}
 
@@ -318,12 +330,18 @@ void ProcessReceiveEvent(ENetPacket* packet)
 			// so screen updates with green names
 			octr.get()->CountPressX = 0;
 			octr.get()->CurrState = LOBBY_START_LOADING;
+#ifdef PINE_DEBUG
+			printf("statechange %d LOBBY_START_LOADING 11: game starting?\n", octr.get()->stateChangeCounter++);
+#endif
 			break;
 		}
 
 		case SG_STARTRACE:
 		{
 			octr.get()->CurrState = GAME_START_RACE;
+#ifdef PINE_DEBUG
+			printf("statechange %d GAME_START_RACE 12: start race\n", octr.get()->stateChangeCounter++);
+#endif
 			break;
 		}
 
@@ -513,6 +531,9 @@ void ProcessNewMessages()
 
 			// to go the lobby browser
 			octr.get()->CurrState = -1;
+#ifdef PINE_DEBUG
+			printf("statechange %d (-1) 13: enet disconnected\n", octr.get()->stateChangeCounter++);
+#endif
 			break;
 
 		default:
@@ -570,6 +591,9 @@ void DisconSELECT()
 
 		// to go the lobby browser
 		octr.get()->CurrState = -1;
+#ifdef PINE_DEBUG
+		printf("statechange %d (-1) 14: pressed SELECT\n", octr.get()->stateChangeCounter++);
+#endif
 		return;
 	}
 }
@@ -591,6 +615,9 @@ void StatePC_Launch_EnterPID()
 	StopAnimation();
 	printf("Client: Waiting to connect to a server...  ");
 	octr.get()->CurrState = LAUNCH_PICK_SERVER;
+#ifdef PINE_DEBUG
+	printf("statechange %d LAUNCH_PICK_SERVER 15: \n", octr.get()->stateChangeCounter++);
+#endif
 }
 
 void printUntilPeriod(const char* str)
@@ -855,7 +882,10 @@ void StatePC_Launch_PickServer()
 			if (retryCount >= MAX_RETRIES)
 			{
 				// to go the country select
-				octr.get()->CurrState = 1;
+				octr.get()->CurrState = LAUNCH_PICK_SERVER;
+#ifdef PINE_DEBUG
+				printf("statechange %d LAUNCH_PICK_SERVER 16: failed to connect to server due to exceeding max retries\n", octr.get()->stateChangeCounter++);
+#endif
 				octr.get()->boolClientBusy = 0;
 				//unlike the above call to blockingWrite() in this function for octr, I don't think this is
 				//necessary, but I'm doing it to be safe.
@@ -872,6 +902,9 @@ void StatePC_Launch_PickServer()
 
 	octr.get()->DriverID = -1;
 	octr.get()->CurrState = LAUNCH_PICK_ROOM;
+#ifdef PINE_DEBUG
+	printf("statechange %d LAUNCH_PICK_SERVER 17: failed to connect to server due to disconnect\n", octr.get()->stateChangeCounter++);
+#endif
 	octr.get()->boolClientBusy = 0;
 	//unlike the above call to blockingWrite() in this function for octr, I don't think this is
 	//necessary, but I'm doing it to be safe.
@@ -958,6 +991,9 @@ void StatePC_Lobby_HostTrackPick()
 	sendToHostReliable(&mt, sizeof(CG_MessageTrack));
 
 	(octr.get())->CurrState = LOBBY_CHARACTER_PICK;
+#ifdef PINE_DEBUG
+	printf("statechange %d LOBBY_CHARACTER_PICK 18: track selected\n", octr.get()->stateChangeCounter++);
+#endif
 }
 
 int prev_characterID = -1;
@@ -994,6 +1030,9 @@ void StatePC_Lobby_CharacterPick()
 	if (mc.boolLockedIn == 1)
 	{
 		octr.get()->CurrState = LOBBY_WAIT_FOR_LOADING;
+#ifdef PINE_DEBUG
+		printf("statechange %d LOBBY_WAIT_FOR_LOADING 19: waiting for game load\n", octr.get()->stateChangeCounter++);
+#endif
 	}
 }
 

mods/Windows/OnlineCTR/Network_PC/Client/DeferredMem.cpp

@@ -213,9 +213,7 @@ internalPineApiID pineSend(DSPINESend sendObj)
 	return pineSendsCount++;
 }
 
-std::mutex waitPineDataMutex;
 std::condition_variable waitPineDataCV;
-std::atomic<bool> recvRan = false;
 
 void pineRecv()
 { //on another thread
@@ -274,12 +272,10 @@ void pineRecv()
 		auto& e = pineObjs.at(pineRecvsCount);
 		e.first.recvData = recvData;
 		e.second = true;
+		pineRecvsCount++;
+		waitPineDataCV.notify_all();
 	}
 	//end critical region
-	pineRecvsCount++;
-	std::unique_lock<std::mutex> ul { waitPineDataMutex };
-	recvRan = true;
-	waitPineDataCV.notify_all();
 }
 
 pineApiID pineApiRequestCount = 0;
@@ -325,13 +321,20 @@ void GCDeadPineData()
 	//end critical region
 }
 
+/// <summary>
+/// Checks if all the data correlated with a single pineApiID has been fully recieved.
+///
+/// !!!WARNING!!! Callers of this function must acquire the "pineObjsMutex" before calling.
+/// This function is internal, and should not be called outside the API.
+/// </summary>
 bool isPineDataPresent(pineApiID id)
 {
 	bool isAllPresent = true;
 	auto& dat = pineApiRequests.at(id).first;
 	//critical region (syncronize access pls)
 	{
-		std::lock_guard<std::mutex> um{ pineObjsMutex };
+		//CALLERS MUST ACQUIRE THIS MUTEX BEFORE CALLING!
+		//std::lock_guard<std::mutex> um{ pineObjsMutex };
 		for (size_t i = 0; i < dat.size(); i++)
 		{
 			isAllPresent &= pineObjs.at(dat[i]).second; //this bool is only true when it's been recvd
@@ -343,15 +346,11 @@ bool isPineDataPresent(pineApiID id)
 
 void waitUntilPineDataPresent(pineApiID id)
 {
-	std::unique_lock<std::mutex> ul{ waitPineDataMutex };
-	while (!isPineDataPresent(id))
-	{
-		while (!recvRan)
-		{
-			waitPineDataCV.wait(ul);
-		}
-		recvRan = false;
-	}
+	std::unique_lock<std::mutex> ul{ pineObjsMutex };
+	//its possible that after we've acquired the mutex, the data arrives, but it arrives
+	//BEFORE the .wait call, (i.e., waitPineDataCV.notify_all() gets called before .wait()), leading to deadlock.
+	if (!isPineDataPresent(id))
+		waitPineDataCV.wait(ul, [id] { return isPineDataPresent(id); });
 }
 
 std::vector<DSPINESendRecvPair> getPineDataSegment(pineApiID id)