From 89f4246e8325bba90cd11a5d85238462c0623776 Mon Sep 17 00:00:00 2001 From: Eric House Date: Thu, 24 May 2018 21:03:25 -0700 Subject: [PATCH] track and log types of (un-acked) messages --- xwords4/relay/udpack.cpp | 45 ++++++++++++++++++++---------------- xwords4/relay/udpack.h | 35 +++++++++++++++++++++------- xwords4/relay/xwrelay.cpp | 6 ++--- xwords4/relay/xwrelay_priv.h | 1 + 4 files changed, 56 insertions(+), 31 deletions(-) diff --git a/xwords4/relay/udpack.cpp b/xwords4/relay/udpack.cpp index a62b24998..5e3e9e7fc 100644 --- a/xwords4/relay/udpack.cpp +++ b/xwords4/relay/udpack.cpp @@ -35,16 +35,16 @@ UDPAckTrack::nextPacketID( XWRelayReg cmd ) { uint32_t result = 0; if ( shouldAck( cmd ) ) { - result = get()->nextPacketIDImpl(); + result = get()->nextPacketIDImpl( cmd ); assert( PACKETID_NONE != result ); } return result; } -/* static*/ void +/* static*/ string UDPAckTrack::recordAck( uint32_t packetID ) { - get()->recordAckImpl( packetID ); + return get()->recordAckImpl( packetID ); } /* static */ bool @@ -97,33 +97,37 @@ UDPAckTrack::ackLimit() } uint32_t -UDPAckTrack::nextPacketIDImpl() +UDPAckTrack::nextPacketIDImpl( XWRelayReg cmd ) { MutexLock ml( &m_mutex ); uint32_t result = ++m_nextID; - AckRecord record; + AckRecord record( cmd , result ); m_pendings.insert( pair(result, record) ); return result; } -void +string UDPAckTrack::recordAckImpl( uint32_t packetID ) { + string str; map::iterator iter; MutexLock ml( &m_mutex ); iter = m_pendings.find( packetID ); if ( m_pendings.end() == iter ) { logf( XW_LOGERROR, "%s: packet ID %d not found", __func__, packetID ); } else { - time_t took = time( NULL ) - iter->second.m_createTime; + AckRecord& rec = iter->second; + str = rec.toStr(); + time_t took = time( NULL ) - rec.m_createTime; if ( 5 < took ) { - logf( XW_LOGERROR, "%s: packet ID %d took %d seconds to get acked", - __func__, packetID, took ); + logf( XW_LOGERROR, "%s: packet %s took %d seconds to get acked", + __func__, str.c_str(), took ); } callProc( iter, true ); m_pendings.erase( iter ); } + return str; } bool @@ -134,8 +138,8 @@ UDPAckTrack::setOnAckImpl( OnAckProc proc, uint32_t packetID, void* data ) MutexLock ml( &m_mutex ); map::iterator iter = m_pendings.find( packetID ); if ( m_pendings.end() != iter ) { - iter->second.proc = proc; - iter->second.data = data; + iter->second.m_proc = proc; + iter->second.m_data = data; } } return canAdd; @@ -180,12 +184,12 @@ void UDPAckTrack::callProc( const map::iterator iter, bool acked ) { const AckRecord* record = &(iter->second); - OnAckProc proc = record->proc; + OnAckProc proc = record->m_proc; if ( NULL != proc ) { uint32_t packetID = iter->first; logf( XW_LOGINFO, "%s(packetID=%d, acked=%d, proc=%p)", __func__, packetID, acked, proc ); - (*proc)( acked, packetID, record->data ); + (*proc)( acked, packetID, record->m_data ); } } @@ -195,15 +199,16 @@ UDPAckTrack::threadProc() for ( ; ; ) { time_t limit = ackLimit(); sleep( limit / 2 ); - vector older; + vector older; { MutexLock ml( &m_mutex ); time_t now = time( NULL ); map::iterator iter; for ( iter = m_pendings.begin(); m_pendings.end() != iter; ) { - time_t took = now - iter->second.m_createTime; + AckRecord& rec = iter->second; + time_t took = now - rec.m_createTime; if ( limit < took ) { - older.push_back( iter->first ); + older.push_back( rec.toStr() ); callProc( iter, false ); m_pendings.erase( iter++ ); } else { @@ -212,14 +217,14 @@ UDPAckTrack::threadProc() } } if ( 0 < older.size() ) { - StrWPF leaked; - vector::const_iterator iter = older.begin(); + string leaked; + vector::const_iterator iter = older.begin(); for ( ; ; ) { - leaked.catf( "%d", *iter ); + leaked += iter->c_str(); if ( ++iter == older.end() ) { break; } - leaked.catf( ", " ); + leaked += ", "; } logf( XW_LOGERROR, "%s: these packets leaked (were not ack'd " "within %d seconds): %s", __func__, diff --git a/xwords4/relay/udpack.h b/xwords4/relay/udpack.h index d7e6d453c..b11166eb8 100644 --- a/xwords4/relay/udpack.h +++ b/xwords4/relay/udpack.h @@ -1,6 +1,7 @@ -/* -*- compile-command: "make MEMDEBUG=TRUE -j3"; -*- */ +/* -*- compile-command: "make -j3"; -*- */ /* - * Copyright 2013 by Eric House (xwords@eehouse.org). All rights reserved. + * Copyright 2013 - 2018 by Eric House (xwords@eehouse.org). All rights + * reserved. * * This program is free software; you can redistribute it and/or * modify it under the terms of the GNU General Public License @@ -20,6 +21,8 @@ #ifndef _UDPACK_H_ #define _UDPACK_H_ +#include + #include "xwrelay_priv.h" #include "xwrelay.h" #include "strwpf.h" @@ -28,10 +31,26 @@ typedef void (*OnAckProc)( bool acked, uint32_t packetID, void* data ); class AckRecord { public: - AckRecord() { m_createTime = time( NULL ); proc = NULL; } + AckRecord( XWRelayReg cmd, uint32_t id ) { + m_createTime = time( NULL ); + m_proc = NULL; + m_cmd = cmd; + m_id = id; + } + + string toStr() + { + char buf[64]; + sprintf( buf, "%d/%s", m_id, msgToStr( m_cmd ) ); + string str(buf); + return str; + } time_t m_createTime; - OnAckProc proc; - void* data; + OnAckProc m_proc; + XWRelayReg m_cmd; + void* m_data; + private: + uint32_t m_id; }; class UDPAckTrack { @@ -39,7 +58,7 @@ class UDPAckTrack { static const uint32_t PACKETID_NONE = 0; static uint32_t nextPacketID( XWRelayReg cmd ); - static void recordAck( uint32_t packetID ); + static string recordAck( uint32_t packetID ); static bool setOnAck( OnAckProc proc, uint32_t packetID, void* data ); static bool shouldAck( XWRelayReg cmd ); /* called from ctrl port */ @@ -51,8 +70,8 @@ class UDPAckTrack { static void* thread_main( void* arg ); UDPAckTrack(); time_t ackLimit(); - uint32_t nextPacketIDImpl(); - void recordAckImpl( uint32_t packetID ); + uint32_t nextPacketIDImpl( XWRelayReg cmd ); + string recordAckImpl( uint32_t packetID ); bool setOnAckImpl( OnAckProc proc, uint32_t packetID, void* data ); void callProc( const map::iterator iter, bool acked ); void printAcksImpl( StrWPF& out ); diff --git a/xwords4/relay/xwrelay.cpp b/xwords4/relay/xwrelay.cpp index 689067f8f..6ec028328 100644 --- a/xwords4/relay/xwrelay.cpp +++ b/xwords4/relay/xwrelay.cpp @@ -1702,7 +1702,7 @@ retrieveMessages( DevID& devID, const AddrInfo* addr ) } } -static const char* +const char* msgToStr( XWRelayReg msg ) { const char* str; @@ -1855,8 +1855,8 @@ handle_udp_packet( PacketThreadClosure* ptc ) case XWPDEV_ACK: { uint32_t packetID; if ( vli2un( &ptr, end, &packetID ) ) { - logf( XW_LOGINFO, "%s: got ack for packet %d", __func__, packetID ); - UDPAckTrack::recordAck( packetID ); + string str = UDPAckTrack::recordAck( packetID ); + logf( XW_LOGINFO, "%s: got ack for packet %s", __func__, str.c_str() ); } break; } diff --git a/xwords4/relay/xwrelay_priv.h b/xwords4/relay/xwrelay_priv.h index ee85f98c7..357dfe54d 100644 --- a/xwords4/relay/xwrelay_priv.h +++ b/xwords4/relay/xwrelay_priv.h @@ -69,6 +69,7 @@ int read_packet( int sock, uint8_t* buf, int buflen ); void onMsgAcked( bool acked, uint32_t packetID, void* data ); const char* cmdToStr( XWRELAY_Cmd cmd ); +const char* msgToStr( XWRelayReg msg ); extern class ListenerMgr g_listeners;