From 4ad735124c7deca3ee07467b43aeb43587a0091e Mon Sep 17 00:00:00 2001
From: Eric House <eehouse@eehouse.org>
Date: Mon, 20 Sep 2010 22:11:13 -0700
Subject: [PATCH] add logging and assertions.  There's a race condition in cref
 recycling and may be one in tpool socket checking-out.

---
 xwords4/relay/crefmgr.h |  9 +++++++++
 xwords4/relay/tpool.cpp | 19 +++++++------------
 xwords4/relay/tpool.h   |  2 +-
 3 files changed, 17 insertions(+), 13 deletions(-)

diff --git a/xwords4/relay/crefmgr.h b/xwords4/relay/crefmgr.h
index aa8686261..830b0ec3c 100644
--- a/xwords4/relay/crefmgr.h
+++ b/xwords4/relay/crefmgr.h
@@ -204,6 +204,7 @@ class SafeCref {
 
     bool Forward( HostID src, HostID dest, unsigned char* buf, int buflen ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_Forward( src, dest, buf, buflen );
             return true;
         } else {
@@ -212,6 +213,7 @@ class SafeCref {
     }
     bool Connect( int socket, int nPlayersH, int nPlayersS, int seed ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             return m_cref->_Connect( socket, nPlayersH, nPlayersS, seed );
         } else {
             return false;
@@ -220,6 +222,7 @@ class SafeCref {
     bool Reconnect( int socket, HostID srcID, int nPlayersH, int nPlayersS,
                     int seed ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_Reconnect( socket, srcID, nPlayersH, nPlayersS, seed );
             return true;
         } else {
@@ -228,11 +231,13 @@ class SafeCref {
     }
     void Disconnect(int socket, HostID hostID ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_Disconnect( socket, hostID );
         }
     }
     bool HandleAck(HostID hostID ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_HandleAck( hostID );
             return true;
         } else {
@@ -241,11 +246,13 @@ class SafeCref {
     }
     void Shutdown() {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_Shutdown();
         }
     }
     void Remove( int socket ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_Remove( socket );
         }
     }
@@ -253,6 +260,7 @@ class SafeCref {
 #ifdef RELAY_HEARTBEAT
     bool HandleHeartbeat( HostID id, int socket ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_HandleHeartbeat( id, socket );
             return true;
         } else {
@@ -261,6 +269,7 @@ class SafeCref {
     }
     void CheckHeartbeats( time_t now ) {
         if ( IsValid() ) {
+            assert( 0 != m_cref->GetCookieID() );
             m_cref->_CheckHeartbeats( now );
         }
     }
diff --git a/xwords4/relay/tpool.cpp b/xwords4/relay/tpool.cpp
index de30c47eb..8766d367e 100644
--- a/xwords4/relay/tpool.cpp
+++ b/xwords4/relay/tpool.cpp
@@ -228,12 +228,13 @@ XWThreadPool::real_tpool_main()
         }
 
         if ( m_timeToDie ) {
+            logf( XW_LOGINFO, "%s: unlocking b/c m_timeToDie set", __func__ );
             pthread_mutex_unlock( &m_queueMutex );
             break;
         }
 
         QueuePr pr;
-        grab_elem_locked( socket, &pr );
+        grab_elem_locked( &pr );
 
         pthread_mutex_unlock( &m_queueMutex );
 
@@ -408,30 +409,24 @@ XWThreadPool::enqueue( int socket, QAction act )
 }
 
 void
-XWThreadPool::grab_elem_locked( int curSock, QueuePr* prp )
+XWThreadPool::grab_elem_locked( QueuePr* prp )
 {
+    logf( XW_LOGINFO, "%s()", __func__ );
     bool found = false;
     prp->m_socket = -1;
     deque<QueuePr>::iterator iter;
     for ( iter = m_queue.begin(); !found && iter != m_queue.end(); ++iter ) {
         int socket = iter->m_socket;
-        if ( socket == curSock 
-             || m_sockets_in_use.end() == m_sockets_in_use.find( socket ) ) {
+        if ( m_sockets_in_use.end() == m_sockets_in_use.find( socket ) ) {
             *prp = *iter;
-            m_queue.erase( iter );
+            m_queue.erase( iter ); /* double-free! */
             m_sockets_in_use.insert( socket );
             found = true;
         }
     }
 
-    /* I think once an event isn't "found" here there's a chance of events
-       sitting in the queue without the threads knowing to go after them.  So
-       IFF this happens need to deal with it or at least confirm that there's
-       no chance of starvation */
-    // assert( found ); THIS IS FIRING
-
     logf( XW_LOGINFO, "%s()=>%d", __func__, found );
-}
+} /* grab_elem_locked */
 
 void
 XWThreadPool::release_socket_locked( int socket )
diff --git a/xwords4/relay/tpool.h b/xwords4/relay/tpool.h
index a1e28e45d..555071ce3 100644
--- a/xwords4/relay/tpool.h
+++ b/xwords4/relay/tpool.h
@@ -61,7 +61,7 @@ class XWThreadPool {
 
     void enqueue( int socket, QAction act = Q_READ );
     void release_socket_locked( int socket );
-    void grab_elem_locked( int curSock, QueuePr* qpp );
+    void grab_elem_locked( QueuePr* qpp );
 
     bool get_process_packet( int socket );
     void interrupt_poll();