diff --git a/CLI/CLI.cpp b/CLI/CLI.cpp index 32f51d8..dd559e0 100644 --- a/CLI/CLI.cpp +++ b/CLI/CLI.cpp @@ -769,6 +769,30 @@ int crashme(int argc, char** argv, ostream& os) } +int stats(int argc, char** argv, ostream& os) +{ + + char cmd[200]; + if (argc==2) + sprintf(cmd,"sqlite3 %s 'select name||\": \"||value||\" events over \"||((%lu-clearedtime)/60)||\" minutes\" from reporting where name like \"%%%s%%\";'", + gConfig.getStr("Control.Reporting.StatsTable").c_str(), time(NULL), argv[1]); + else if (argc==1) + sprintf(cmd,"sqlite3 %s 'select name||\": \"||value||\" events over \"||((%lu-clearedtime)/60)||\" minutes\" from reporting;'", + gConfig.getStr("Control.Reporting.StatsTable").c_str(), time(NULL)); + else return BAD_NUM_ARGS; + FILE *result = popen(cmd,"r"); + char *line = (char*)malloc(200); + while (!feof(result)) { + if (!fgets(line, 200, result)) break; + os << line; + } + free(line); + os << endl; + pclose(result); + return SUCCESS; +} + + //@} // CLI commands @@ -800,6 +824,7 @@ void Parser::addCommands() addCommand("notices", notices, "-- show startup copyright and legal notices"); addCommand("endcall", endcall,"trans# -- terminate the given transaction"); addCommand("crashme", crashme, "force crash of OpenBTS for testing purposes"); + addCommand("stats", stats,"[patt] -- print all, or selected, performance statistics"); } diff --git a/CommonLibs/Configuration.h b/CommonLibs/Configuration.h index 0b14633..3377e6d 100644 --- a/CommonLibs/Configuration.h +++ b/CommonLibs/Configuration.h @@ -1,6 +1,7 @@ /* * Copyright 2009, 2010 Free Software Foundation, Inc. -* Copyright 2010, 2012 Kestrel Signal Processing, Inc. +* Copyright 2010 Kestrel Signal Processing, Inc. +* Copyright 2011, 2012 Range Networks, Inc. * * This software is distributed under the terms of the GNU Affero Public License. * See the COPYING file in the main directory for details. diff --git a/CommonLibs/Makefile.am b/CommonLibs/Makefile.am index 6bba671..624ba44 100644 --- a/CommonLibs/Makefile.am +++ b/CommonLibs/Makefile.am @@ -1,5 +1,6 @@ # # Copyright 2008, 2009 Free Software Foundation, Inc. +# Copyright 2011, 2012 Range Networks, Inc. # # This software is distributed under the terms of the GNU Public License. # See the COPYING file in the main directory for details. @@ -31,10 +32,11 @@ libcommon_la_SOURCES = \ Sockets.cpp \ Threads.cpp \ Timeval.cpp \ + Configuration.cpp \ + sqlite3util.cpp \ Logger.cpp \ URLEncode.cpp \ - Configuration.cpp \ - sqlite3util.cpp + Reporting.cpp noinst_PROGRAMS = \ BitVectorTest \ @@ -47,6 +49,8 @@ noinst_PROGRAMS = \ LogTest \ F16Test +# ReportingTest + noinst_HEADERS = \ BitVector.h \ Interthread.h \ @@ -58,6 +62,7 @@ noinst_HEADERS = \ Vector.h \ URLEncode.h \ Configuration.h \ + Reporting.h \ F16.h \ Logger.h \ sqlite3util.h @@ -85,6 +90,9 @@ RegexpTest_LDADD = libcommon.la ConfigurationTest_SOURCES = ConfigurationTest.cpp ConfigurationTest_LDADD = libcommon.la $(SQLITE_LA) +#ReportingTest_SOURCES = ReportingTest.cpp +#ReportingTest_LDADD = libcommon.la $(SQLITE_LA) + LogTest_SOURCES = LogTest.cpp LogTest_LDADD = libcommon.la $(SQLITE_LA) diff --git a/Control/CallControl.cpp b/Control/CallControl.cpp index cd27b68..eec64ad 100644 --- a/Control/CallControl.cpp +++ b/Control/CallControl.cpp @@ -57,6 +57,7 @@ #include #include +#include #undef WARNING using namespace std; @@ -328,6 +329,7 @@ bool callManagementDispatchGSM(TransactionEntry *transaction, GSM::LogicalChanne // GSM 04.08 5.4.3.2 if (const GSM::L3Disconnect *disc = dynamic_cast(message)) { LOG(INFO) << "GSM Disconnect " << *transaction; + gReports.incr("OpenBTS.GSM.CC.MOD.Disconnect"); bool early = transaction->GSMState() != GSM::Active; bool normal = (disc->cause().cause() <= 0x10); if (!normal) { @@ -379,6 +381,7 @@ bool callManagementDispatchGSM(TransactionEntry *transaction, GSM::LogicalChanne // Release (2nd step of MTD) if (dynamic_cast(message)) { LOG(INFO) << "GSM Release " << *transaction; + gReports.incr("OpenBTS.GSM.CC.MTD.Release"); /* late RLLP request */ if (gConfig.defines("Control.Call.QueryRRLP.Late")) { // Query for RRLP @@ -720,6 +723,7 @@ bool waitInCall(TransactionEntry *transaction, GSM::TCHFACCHLogicalChannel *TCH, void callManagementLoop(TransactionEntry *transaction, GSM::TCHFACCHLogicalChannel* TCH) { LOG(INFO) << " call connected " << *transaction; + gReports.incr("OpenBTS.GSM.CC.CallMinutes"); // poll everything until the call is finished while (!pollInCall(transaction,TCH)) { } gTransactionTable.remove(transaction); @@ -791,6 +795,8 @@ void Control::MOCStarter(const GSM::L3CMServiceRequest* req, GSM::LogicalChannel throw UnexpectedMessage(); } + gReports.incr("OpenBTS.GSM.CC.MOC.Setup"); + /* early RLLP request */ /* this seems to need to be sent after initial call setup -kurtis */ @@ -1048,6 +1054,7 @@ void Control::MTCStarter(TransactionEntry *transaction, GSM::LogicalChannel *LCH // GSM 04.08 5.2.2.1 LOG(INFO) << "sending GSM Setup to call " << transaction->calling(); LCH->send(GSM::L3Setup(L3TI,GSM::L3CallingPartyBCDNumber(transaction->calling()))); + gReports.incr("OpenBTS.GSM.CC.MTC.Setup"); transaction->setTimer("303"); transaction->GSMState(GSM::CallPresent); diff --git a/Control/ControlCommon.cpp b/Control/ControlCommon.cpp index 4833d88..cbef479 100644 --- a/Control/ControlCommon.cpp +++ b/Control/ControlCommon.cpp @@ -39,6 +39,7 @@ #include #include +#include #undef WARNING diff --git a/Control/DCCHDispatch.cpp b/Control/DCCHDispatch.cpp index ee72496..3a25d5c 100644 --- a/Control/DCCHDispatch.cpp +++ b/Control/DCCHDispatch.cpp @@ -40,6 +40,8 @@ #include #undef WARNING +#include +#include using namespace std; using namespace GSM; @@ -130,6 +132,7 @@ void Control::DCCHDispatcher(LogicalChannel *DCCH) LOG(DEBUG) << "waiting for " << *DCCH << " ESTABLISH"; DCCH->waitForPrimitive(ESTABLISH); // Pull the first message and dispatch a new transaction. + gReports.incr("OpenBTS.GSM.RR.ChannelSiezed"); const L3Message *message = getMessage(DCCH); LOG(DEBUG) << *DCCH << " received " << *message; DCCHDispatchMessage(message,DCCH); diff --git a/Control/MobilityManagement.cpp b/Control/MobilityManagement.cpp index a211d69..12cff67 100644 --- a/Control/MobilityManagement.cpp +++ b/Control/MobilityManagement.cpp @@ -50,6 +50,7 @@ using namespace std; using namespace SIP; #include +#include #include #undef WARNING @@ -66,12 +67,15 @@ void Control::CMServiceResponder(const L3CMServiceRequest* cmsrq, LogicalChannel LOG(INFO) << *cmsrq; switch (cmsrq->serviceType().type()) { case L3CMServiceType::MobileOriginatedCall: + gReports.incr("OpenBTS.GSM.MM.CMServiceRequest.MOC"); MOCStarter(cmsrq,DCCH); break; case L3CMServiceType::ShortMessage: + gReports.incr("OpenBTS.GSM.MM.CMServiceRequest.MOSMS"); MOSMSController(cmsrq,DCCH); break; default: + gReports.incr("OpenBTS.GSM.MM.CMServiceRequest.Unhandled"); LOG(NOTICE) << "service not supported for " << *cmsrq; // Cause 0x20 means "serivce not supported". DCCH->send(L3CMServiceReject(0x20)); @@ -145,10 +149,11 @@ void Control::LocationUpdatingController(const L3LocationUpdatingRequest* lur, L LOG(INFO) << *lur; // The location updating request gets mapped to a SIP - // registration with the Asterisk server. + // registration with the SIP registrar. // We also allocate a new TMSI for every handset we encounter. // If the handset is allowed to register it may receive a TMSI reassignment. + gReports.incr("OpenBTS.GSM.MM.LUR.Start"); // Resolve an IMSI and see if there's a pre-existing IMSI-TMSI mapping. // This operation will throw an exception, caught in a higher scope, @@ -177,6 +182,7 @@ void Control::LocationUpdatingController(const L3LocationUpdatingRequest* lur, L LOG(ALERT) "SIP registration timed out. Is the proxy running at " << gConfig.getStr("SIP.Proxy.Registration"); // Reject with a "network failure" cause code, 0x11. DCCH->send(L3LocationUpdatingReject(0x11)); + gReports.incr("OpenBTS.GSM.MM.LUR.Timeout"); // HACK -- wait long enough for a response // FIXME -- Why are we doing this? sleep(4); diff --git a/Control/RRLPServer.cpp b/Control/RRLPServer.cpp index 6a676be..1231457 100644 --- a/Control/RRLPServer.cpp +++ b/Control/RRLPServer.cpp @@ -36,6 +36,7 @@ using namespace std; #include #include +#include using namespace GSM; using namespace Control; diff --git a/Control/RadioResource.cpp b/Control/RadioResource.cpp index e027e64..f5b9058 100644 --- a/Control/RadioResource.cpp +++ b/Control/RadioResource.cpp @@ -42,6 +42,7 @@ #include #include +#include #include #undef WARNING @@ -132,6 +133,9 @@ void AccessGrantResponder( // This GSM's version of medium access control. // Papa Legba, open that door... + gReports.incr("OpenBTS.GSM.RR.RACH.TA.All",(int)(timingError)); + gReports.incr("OpenBTS.GSM.RR.RACH.RA.All",RA); + // Are we holding off new allocations? if (gBTS.hold()) { LOG(NOTICE) << "ignoring RACH due to BTS hold-off"; @@ -214,6 +218,7 @@ void AccessGrantResponder( // Set the channel physical parameters from the RACH burst. LCH->setPhy(RSSI,timingError); + gReports.incr("OpenBTS.GSM.RR.RACH.TA.Accepted",(int)(timingError)); // Assignment, GSM 04.08 3.3.1.1.3.1. // Create the ImmediateAssignment message. diff --git a/Control/SMSControl.cpp b/Control/SMSControl.cpp index f5fcb0a..122a7bc 100644 --- a/Control/SMSControl.cpp +++ b/Control/SMSControl.cpp @@ -50,6 +50,7 @@ #include "TransactionTable.h" #include "RRLPServer.h" #include +#include @@ -213,6 +214,8 @@ void Control::MOSMSController(const GSM::L3CMServiceRequest *req, GSM::LogicalCh // The first read on SAP3 is the ESTABLISH primitive. delete getFrameSMS(LCH,GSM::ESTABLISH); + gReports.incr("OpenBTS.GSM.SMS.MOSMS.Start"); + // Step 1 // Now get the first message. // Should be CP-DATA, containing RP-DATA. @@ -287,6 +290,8 @@ void Control::MOSMSController(const GSM::L3CMServiceRequest *req, GSM::LogicalCh delete CM; LOG(INFO) << "CPAck " << ack; + gReports.incr("OpenBTS.GSM.SMS.MOSMS.Complete"); + /* MOSMS RLLP request */ if (gConfig.defines("Control.SMS.QueryRRLP")) { // Query for RRLP @@ -372,6 +377,8 @@ bool Control::deliverSMSToMS(const char *callingPartyDigits, const char* message #endif + gReports.incr("OpenBTS.GSM.SMS.MTSMS.Start"); + // Start ABM in SAP3. //LCH->send(GSM::ESTABLISH,3); // Wait for SAP3 ABM to connect. @@ -435,6 +442,8 @@ bool Control::deliverSMSToMS(const char *callingPartyDigits, const char* message success = false; } + gReports.incr("OpenBTS.GSM.SMS.MTSMS.Complete"); + // Step 4 // Send CP-ACK to the MS. LOG(INFO) << "MTSMS: sending CPAck"; diff --git a/Control/TMSITable.cpp b/Control/TMSITable.cpp index 142fb73..01d40dd 100644 --- a/Control/TMSITable.cpp +++ b/Control/TMSITable.cpp @@ -31,6 +31,8 @@ #include #include +#include +#include #include #include @@ -95,6 +97,8 @@ unsigned TMSITable::assign(const char* IMSI, const GSM::L3LocationUpdatingReques // Return assigned TMSI. assert(mDB); + gReports.incr("OpenBTS.GSM.MM.TMSI.Assigned"); + LOG(DEBUG) << "IMSI=" << IMSI; // Is there already a record? unsigned TMSI; diff --git a/Control/TransactionTable.cpp b/Control/TransactionTable.cpp index 77b1d0f..a5f6855 100644 --- a/Control/TransactionTable.cpp +++ b/Control/TransactionTable.cpp @@ -38,6 +38,7 @@ #include +#include #include #undef WARNING diff --git a/GSM/GSMConfig.cpp b/GSM/GSMConfig.cpp index 44da89f..736713e 100644 --- a/GSM/GSMConfig.cpp +++ b/GSM/GSMConfig.cpp @@ -28,7 +28,8 @@ #include "GSMLogicalChannel.h" #include #include - +#include +#include using namespace std; @@ -64,6 +65,8 @@ void GSMConfig::start() void GSMConfig::regenerateBeacon() { + gReports.incr("OpenBTS.GSM.RR.BeaconRegenerated"); + // Update everything from the configuration. LOG(NOTICE) << "regenerating system information messages"; @@ -188,7 +191,10 @@ TCHFACCHLogicalChannel *GSMConfig::getTCH() { ScopedLock lock(mLock); TCHFACCHLogicalChannel *chan = getChan(mTCHPool); - if (chan) chan->open(); + if (chan) { + chan->open(); + gReports.incr("OpenBTS.GSM.RR.ChannelAssignment"); + } return chan; } diff --git a/Globals/Globals.h b/Globals/Globals.h index 0fe1fb3..e6c0f72 100644 --- a/Globals/Globals.h +++ b/Globals/Globals.h @@ -36,6 +36,7 @@ #include #include #include +#include @@ -66,4 +67,5 @@ extern GSM::PhysicalStatus gPhysStatus; /** The subscriber registry */ extern SubscriberRegistry gSubscriberRegistry; +extern ReportingTable gReports; #endif diff --git a/SIP/SIPEngine.cpp b/SIP/SIPEngine.cpp index 373c675..7c09f62 100644 --- a/SIP/SIPEngine.cpp +++ b/SIP/SIPEngine.cpp @@ -1,7 +1,7 @@ /**@file SIP Call Control -- SIP IETF RFC-3261, RTP IETF RFC-3550. */ /* * Copyright 2008, 2009, 2010, 2011 Free Software Foundation, Inc. -* Copyright 2011 Range Networks, Inc. +* Copyright 2011, 2012 Range Networks, Inc. * * This software is distributed under the terms of the GNU Affero Public License. * See the COPYING file in the main directory for details. @@ -41,6 +41,8 @@ #include #include #include +#include +#include #include "SIPInterface.h" #include "SIPUtility.h" @@ -342,6 +344,9 @@ bool SIPEngine::Register( Method wMethod ) mViaBranch.c_str(), mCallID.c_str(), mCSeq ); } else { assert(0); } + + //writePrivateHeaders(reg,chan); + gReports.incr("OpenBTS.SIP.REGISTER.Out"); LOG(DEBUG) << "writing registration " << reg; gSIPInterface.write(&mProxyAddr,reg); @@ -356,6 +361,7 @@ bool SIPEngine::Register( Method wMethod ) msg = gSIPInterface.read(mCallID, gConfig.getNum("SIP.Timer.E")); } catch (SIPTimeout) { // send again + LOG(NOTICE) << "SIP REGISTER packet to " << mProxyIP << ":" << mProxyPort << " timeout; resending"; gSIPInterface.write(&mProxyAddr,reg); continue; } @@ -427,6 +433,7 @@ SIPState SIPEngine::SOSSendINVITE(short wRtp_port, unsigned wCodec, const GSM:: LOG(INFO) << "user " << mSIPUsername << " state " << mState; // Before start, need to add mCallID gSIPInterface.addCall(mCallID); + gReports.incr("OpenBTS.SIP.INVITE-SOS.Out"); // Set Invite params. // new CSEQ and codec @@ -489,6 +496,7 @@ SIPState SIPEngine::MOCSendINVITE( const char * wCalledUsername, // Before start, need to add mCallID gSIPInterface.addCall(mCallID); mInstigator = true; + gReports.incr("OpenBTS.SIP.INVITE.Out"); // Set Invite params. // new CSEQ and codec @@ -532,8 +540,10 @@ SIPState SIPEngine::MOCResendINVITE() SIPState SIPEngine::MOCCheckForOK(Mutex *lock) { LOG(INFO) << "user " << mSIPUsername << " state " << mState; + //if (mState==Fail) return Fail; osip_message_t * msg; + //osip_message_t * msg = NULL; // Read off the fifo. if time out will // clean up and return false. @@ -564,22 +574,106 @@ SIPState SIPEngine::MOCCheckForOK(Mutex *lock) case 180: // Ringing mState = Ringing; break; + + // calss 2XX: Success case 200: // OK - // Save the response and update the state, - // but the ACK doesn't happen until the call connects. + // Save the response and update the state, + // but the ACK doesn't happen until the call connects. mState = Active; break; + + // class 3xx: Redirection + case 300: // Multiple Choices + case 301: // Moved Permanently + case 302: // Moved Temporarily + case 305: // Use Proxy + case 380: // Alternative Service + LOG(NOTICE) << "redirection not supported code " << status; + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.3xx"); + MOCSendACK(); + break; // Anything 400 or above terminates the call, so we ACK. // FIXME -- It would be nice to save more information about the // specific failure cause. - case 486: - case 503: + + // class 4XX: Request failures + case 400: // Bad Request + case 401: // Unauthorized: Used only by registrars. Proxys should use proxy authorization 407 + case 402: // Payment Required (Reserved for future use) + case 403: // Forbidden + case 404: // Not Found: User not found + case 405: // Method Not Allowed + case 406: // Not Acceptable + case 407: // Proxy Authentication Required + case 408: // Request Timeout: Couldn't find the user in time + case 409: // Conflict + case 410: // Gone: The user existed once, but is not available here any more. + case 413: // Request Entity Too Large + case 414: // Request-URI Too Long + case 415: // Unsupported Media Type + case 416: // Unsupported URI Scheme + case 420: // Bad Extension: Bad SIP Protocol Extension used, not understood by the server + case 421: // Extension Required + case 422: // Session Interval Too Small + case 423: // Interval Too Brief + case 480: // Temporarily Unavailable + case 481: // Call/Transaction Does Not Exist + case 482: // Loop Detected + case 483: // Too Many Hops + case 484: // Address Incomplete + case 485: // Ambiguous + LOG(NOTICE) << "request failure code " << status; + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.4xx"); + MOCSendACK(); + break; + + case 486: // Busy Here + LOG(NOTICE) << "remote end busy code " << status; mState = Busy; MOCSendACK(); break; + case 487: // Request Terminated + case 488: // Not Acceptable Here + case 491: // Request Pending + case 493: // Undecipherable: Could not decrypt S/MIME body part + LOG(NOTICE) << "request failure code " << status; + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.4xx"); + MOCSendACK(); + break; + + // class 5XX: Server failures + case 500: // Server Internal Error + case 501: // Not Implemented: The SIP request method is not implemented here + case 502: // Bad Gateway + case 503: // Service Unavailable + case 504: // Server Time-out + case 505: // Version Not Supported: The server does not support this version of the SIP protocol + case 513: // Message Too Large + LOG(NOTICE) << "server failure code " << status; + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.5xx"); + MOCSendACK(); + break; + + // class 6XX: Global failures + case 600: // Busy Everywhere + case 603: // Decline + mState = Busy; + MOCSendACK(); + break; + case 604: // Does Not Exist Anywhere + case 606: // Not Acceptable + LOG(NOTICE) << "global failure code " << status; + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.6xx"); + MOCSendACK(); default: LOG(NOTICE) << "unhandled status code " << status; mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.xxx"); MOCSendACK(); } osip_message_free(msg); @@ -613,6 +707,7 @@ SIPState SIPEngine::MODSendBYE() { LOG(INFO) << "user " << mSIPUsername << " state " << mState; assert(mINVITE); + gReports.incr("OpenBTS.SIP.BYE.Out"); char tmp[50]; make_branch(tmp); mViaBranch = tmp; @@ -742,6 +837,8 @@ SIPState SIPEngine::MODWaitForBYEOK(Mutex *lock) osip_message_free(ok); if (code!=200) { LOG(WARNING) << "unexpected " << code << " response to BYE, from proxy " << mProxyIP << ":" << mProxyPort << ". Assuming other end has cleared"; + } else { + gReports.incr("OpenBTS.SIP.BYE-OK.In"); } break; } @@ -751,7 +848,10 @@ SIPState SIPEngine::MODWaitForBYEOK(Mutex *lock) } } - if (!responded) { LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; } + if (!responded) { + LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; + gReports.incr("OpenBTS.SIP.LostProxy"); + } mState = Cleared; @@ -781,7 +881,10 @@ SIPState SIPEngine::MODWaitForCANCELOK(Mutex *lock) } } - if (!responded) { LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; } + if (!responded) { + LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; + gReports.incr("OpenBTS.SIP.LostProxy"); + } mState = Canceled; @@ -861,7 +964,10 @@ SIPState SIPEngine::MODWaitForERRORACK(bool cancel, Mutex *lock) } } - if (!responded) { LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; } + if (!responded) { + LOG(ALERT) << "lost contact with proxy " << mProxyIP << ":" << mProxyPort; + gReports.incr("OpenBTS.SIP.LostProxy"); + } if (cancel){ mState = Canceled; @@ -900,6 +1006,7 @@ SIPState SIPEngine::MTDCheckBYE() if (strcmp(msg->sip_method,"BYE")==0) { LOG(DEBUG) << "found msg="<sip_method; saveBYE(msg,false); + gReports.incr("OpenBTS.SIP.BYE.In"); mState = MTDClearing; } //repeated ACK, send OK @@ -925,6 +1032,7 @@ SIPState SIPEngine::MTDSendBYEOK() { LOG(INFO) << "user " << mSIPUsername << " state " << mState; assert(mBYE); + gReports.incr("OpenBTS.SIP.BYE-OK.Out"); osip_message_t * okay = sip_b_okay(mBYE); gSIPInterface.write(&mProxyAddr,okay); osip_message_free(okay); @@ -947,8 +1055,12 @@ SIPState SIPEngine::MTDSendCANCELOK() SIPState SIPEngine::MTCSendTrying() { LOG(INFO) << "user " << mSIPUsername << " state " << mState; - if (mINVITE==NULL) mState=Fail; + if (mINVITE==NULL) { + mState=Fail; + gReports.incr("OpenBTS.SIP.Failed.Local"); + } if (mState==Fail) return mState; + osip_message_t * trying = sip_trying(mINVITE, mSIPUsername.c_str(), mProxyIP.c_str()); gSIPInterface.write(&mProxyAddr,trying); osip_message_free(trying); @@ -978,6 +1090,7 @@ SIPState SIPEngine::MTCSendOK( short wRTPPort, unsigned wCodec, const GSM::Logic { LOG(INFO) << "user " << mSIPUsername << " state " << mState; assert(mINVITE); + gReports.incr("OpenBTS.SIP.INVITE-OK.Out"); mRTPPort = wRTPPort; mCodec = wCodec; LOG(DEBUG) << "port=" << wRTPPort << " codec=" << mCodec; @@ -998,6 +1111,8 @@ SIPState SIPEngine::MTCCheckForACK(Mutex *lock) // period, need to split into 2 handle situation // like MOC where this fxn if called multiple times. LOG(INFO) << "user " << mSIPUsername << " state " << mState; + //if (mState==Fail) return mState; + //osip_message_t * ack = NULL; osip_message_t * ack; // FIXME -- This is supposed to retransmit BYE on timer I. @@ -1006,17 +1121,20 @@ SIPState SIPEngine::MTCCheckForACK(Mutex *lock) } catch (SIPTimeout& e) { LOG(NOTICE) << "timeout"; - mState = Timeout; + gReports.incr("OpenBTS.SIP.ReadTimeout"); + mState = Timeout; return mState; } catch (SIPError& e) { LOG(NOTICE) << "read error"; + gReports.incr("OpenBTS.SIP.Failed.Local"); mState = Fail; return mState; } if (ack->sip_method==NULL) { LOG(NOTICE) << "SIP message with no method, status " << ack->status_code; + gReports.incr("OpenBTS.SIP.Failed.Local"); mState = Fail; osip_message_free(ack); return mState; @@ -1042,6 +1160,7 @@ SIPState SIPEngine::MTCCheckForACK(Mutex *lock) // check for strays else { LOG(NOTICE) << "unexpected Message "<sip_method; + gReports.incr("OpenBTS.SIP.Failed.Local"); mState = Fail; } @@ -1057,6 +1176,8 @@ SIPState SIPEngine::MTCCheckForCancel() // period, need to split into 2 handle situation // like MOC where this fxn if called multiple times. LOG(INFO) << "user " << mSIPUsername << " state " << mState; + //if (mState=Fail) return Fail; + //osip_message_t * msg = NULL; osip_message_t * msg; try { @@ -1064,17 +1185,22 @@ SIPState SIPEngine::MTCCheckForCancel() msg = gSIPInterface.read(mCallID,1); } catch (SIPTimeout& e) { + gReports.incr("OpenBTS.SIP.ReadTimeout"); return mState; } catch (SIPError& e) { LOG(NOTICE) << "read error"; mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Local"); return mState; } if (msg->sip_method==NULL) { LOG(NOTICE) << "SIP message with no method, status " << msg->status_code; - mState = Fail; + if (mState!=Fail) { + mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Local"); + } osip_message_free(msg); return mState; } @@ -1094,6 +1220,7 @@ SIPState SIPEngine::MTCCheckForCancel() // check for strays else { LOG(NOTICE) << "unexpected Message " << msg->sip_method; + gReports.incr("OpenBTS.SIP.Failed.Local"); mState = Fail; } @@ -1135,8 +1262,8 @@ void SIPEngine::InitRTP(const osip_message_t * msg ) // Check for event support. int code = rtp_session_telephone_events_supported(mSession); if (code == -1) { - if (rfc2833) { LOG(ALERT) << "RTP session does not support selected DTMF method RFC-2833"; } - else { LOG(WARNING) << "RTP session does not support telephone events"; } + if (rfc2833) { LOG(CRIT) << "RTP session does not support selected DTMF method RFC-2833"; } + else { LOG(CRIT) << "RTP session does not support telephone events"; } } } @@ -1250,6 +1377,7 @@ SIPState SIPEngine::MOSMSSendMESSAGE(const char * wCalledUsername, // Before start, need to add mCallID gSIPInterface.addCall(mCallID); mInstigator = true; + gReports.incr("OpenBTS.SIP.MESSAGE.Out"); // Set MESSAGE params. char tmp[50]; @@ -1314,6 +1442,7 @@ SIPState SIPEngine::MOSMSWaitForSubmit(Mutex *lock) //demonstrate that these are not forwarded correctly if (ok->status_code >= 400){ mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Remote.4xx"); LOG (ALERT) << "SIP MESSAGE rejected: " << ok->status_code << " " << ok->reason_phrase; break; } @@ -1325,7 +1454,10 @@ SIPState SIPEngine::MOSMSWaitForSubmit(Mutex *lock) if (!ok) { //changed from "throw SIPTimeout()", as this seems more correct -k mState = Fail; + gReports.incr("OpenBTS.SIP.Failed.Local"); + gReports.incr("OpenBTS.SIP.ReadTimeout"); LOG(ALERT) << "SIP MESSAGE timed out; is the smqueue server " << mProxyIP << ":" << mProxyPort << " OK?"; + gReports.incr("OpenBTS.SIP.LostProxy"); } else { osip_message_free(ok); } @@ -1386,6 +1518,7 @@ bool SIPEngine::sendINFOAndWaitForOK(unsigned wInfo, Mutex *lock) osip_message_free(info); if (!ok) { LOG(ALERT) << "SIP RFC-2967 INFO timed out; is the proxy at " << mProxyIP << ":" << mProxyPort << " OK?"; + gReports.incr("OpenBTS.SIP.LostProxy"); return false; } LOG(DEBUG) << "received status " << ok->status_code << " " << ok->reason_phrase; diff --git a/SIP/SIPInterface.cpp b/SIP/SIPInterface.cpp index 747464d..5919ecf 100644 --- a/SIP/SIPInterface.cpp +++ b/SIP/SIPInterface.cpp @@ -400,12 +400,14 @@ bool SIPInterface::checkInvite( osip_message_t * msg) channelAvailable = gBTS.SDCCHAvailable() && gBTS.TCHAvailable(); } serviceType = L3CMServiceType::MobileTerminatedCall; + gReports.incr("OpenBTS.SIP.INVITE.In"); } else if (strcmp(method,"MESSAGE") == 0) { // MESSAGE is for MTSMS. requiredChannel = GSM::SDCCHType; channelAvailable = gBTS.SDCCHAvailable(); serviceType = L3CMServiceType::MobileTerminatedShortMessage; + gReports.incr("OpenBTS.SIP.MESSAGE.In"); } else { // Not a method handled here. diff --git a/TRXManager/TRXManager.cpp b/TRXManager/TRXManager.cpp index fd04836..6c37f83 100644 --- a/TRXManager/TRXManager.cpp +++ b/TRXManager/TRXManager.cpp @@ -24,6 +24,7 @@ +#include #include "TRXManager.h" #include "GSMCommon.h" @@ -90,6 +91,7 @@ void TransceiverManager::clockHandler() // Did the transceiver die?? if (msgLen<0) { LOG(ALERT) << "TRX clock interface timed out, assuming TRX is dead."; + gReports.incr("OpenBTS.Exit.Error.TransceiverHeartbeat"); abort(); } diff --git a/apps/OpenBTS.cpp b/apps/OpenBTS.cpp index 0b4dd1b..879e80b 100644 --- a/apps/OpenBTS.cpp +++ b/apps/OpenBTS.cpp @@ -31,6 +31,10 @@ // Load configuration from a file. ConfigurationTable gConfig("/etc/OpenBTS/OpenBTS.db"); +// Set up the performance reporter. +#include +ReportingTable gReports(gConfig.getStr("Control.Reporting.StatsTable","/var/log/OpenBTSStats.db").c_str(),LOG_LOCAL7); + #include #include #include @@ -133,6 +137,144 @@ void startTransceiver() +void createStats() +{ + // count of OpenBTS start events + gReports.create("OpenBTS.Starts"); + + // count of exit events driven from the CLI + gReports.create("OpenBTS.Exit.Normal.CLI"); + // count of watchdog restarts + gReports.create("OpenBTS.Exit.Error.Watchdog"); + // count of aborts due to problems with CLI socket + gReports.create("OpenBTS.Exit.Error.CLISocket"); + // count of aborts due to loss of transceiver heartbeat + gReports.create("OpenBTS.Exit.Error.TransceiverHeartbeat"); + // count of aborts due to underfined nono-optional configuration parameters + gReports.create("OpenBTS.Exit.Error.ConfigurationParameterNotFound"); + + // count of CLI commands sent to OpenBTS + gReports.create("OpenBTS.CLI.Command"); + // count of CLI commands where responses could not be returned + gReports.create("OpenBTS.CLI.Command.ResponseFailure"); + + // count of SIP transactions that failed with 3xx responses from the remote end + gReports.create("OpenBTS.SIP.Failed.Remote.3xx"); + // count of SIP transactions that failed with 4xx responses from the remote end + gReports.create("OpenBTS.SIP.Failed.Remote.4xx"); + // count of SIP transactions that failed with 5xx responses from the remote end + gReports.create("OpenBTS.SIP.Failed.Remote.5xx"); + // count of SIP transactions that failed with 6xx responses from the remote end + gReports.create("OpenBTS.SIP.Failed.Remote.6xx"); + // count of SIP transactions that failed with unrecognized responses from the remote end + gReports.create("OpenBTS.SIP.Failed.Remote.xxx"); + // count of SIP transactions that failed due to local-end errors + gReports.create("OpenBTS.SIP.Failed.Local"); + // count of timeout events on SIP socket reads + gReports.create("OpenBTS.SIP.ReadTimeout"); + // count of SIP messages that were never properly acked + gReports.create("OpenBTS.SIP.LostProxy"); + // count of SIP message not sent due to unresolvable host name + gReports.create("OpenBTS.SIP.UnresolvedHostname"); + // count of INVITEs received in the SIP layer + gReports.create("OpenBTS.SIP.INVITE.In"); + // count of SOS INVITEs sent from the SIP layer; these are not included in ..INVITE.OUT + gReports.create("OpenBTS.SIP.INVITE-SOS.Out"); + // count of INVITEs sent from the in SIP layer + gReports.create("OpenBTS.SIP.INVITE.Out"); + // count of INVITE-OKs sent from the in SIP layer (connection established) + gReports.create("OpenBTS.SIP.INVITE-OK.Out"); + // count of MESSAGEs received in the in SIP layer + gReports.create("OpenBTS.SIP.MESSAGE.In"); + // count of MESSAGESs sent from the SIP layer + gReports.create("OpenBTS.SIP.MESSAGE.Out"); + // count of REGISTERSs sent from the SIP layer + gReports.create("OpenBTS.SIP.REGISTER.Out"); + // count of BYEs sent from the SIP layer + gReports.create("OpenBTS.SIP.BYE.Out"); + // count of BYEs received in the SIP layer + gReports.create("OpenBTS.SIP.BYE.In"); + // count of BYE-OKs sent from SIP layer (final disconnect handshake) + gReports.create("OpenBTS.SIP.BYE-OK.Out"); + // count of BYE-OKs received in SIP layer (final disconnect handshake) + gReports.create("OpenBTS.SIP.BYE-OK.In"); + + // count of initiated LUR attempts + gReports.create("OpenBTS.GSM.MM.LUR.Start"); + // count of LUR attempts where the server timed out + gReports.create("OpenBTS.GSM.MM.LUR.Timeout"); + //gReports.create("OpenBTS.GSM.MM.LUR.Success"); + //gReports.create("OpenBTS.GSM.MM.LUR.NotFound"); + //gReports.create("OpenBTS.GSM.MM.LUR.Allowed"); + //gReports.create("OpenBTS.GSM.MM.LUR.Rejected"); + // count of all authentication attempts + gReports.create("OpenBTS.GSM.MM.Authenticate.Request"); + // count of authentication attempts the succeeded + gReports.create("OpenBTS.GSM.MM.Authenticate.Success"); + // count of authentication attempts that failed + gReports.create("OpenBTS.GSM.MM.Authenticate.Failure"); + // count of the number of TMSIs assigned to users + gReports.create("OpenBTS.GSM.MM.TMSI.Assigned"); + //gReports.create("OpenBTS.GSM.MM.TMSI.Unknown"); + // count of CM Service requests for MOC + gReports.create("OpenBTS.GSM.MM.CMServiceRequest.MOC"); + // count of CM Service requests for emergency calls + gReports.create("OpenBTS.GSM.MM.CMServiceRequest.SOS"); + // count of CM Service requests for MOSMS + gReports.create("OpenBTS.GSM.MM.CMServiceRequest.MOSMS"); + // count of CM Service requests for services we don't support + gReports.create("OpenBTS.GSM.MM.CMServiceRequest.Unhandled"); + + // count of mobile-originated SMS submissions initiated + gReports.create("OpenBTS.GSM.SMS.MOSMS.Start"); + // count of mobile-originated SMS submissions competed (got CP-ACK for RP-ACK) + gReports.create("OpenBTS.GSM.SMS.MOSMS.Complete"); + // count of mobile-temrinated SMS deliveries initiated + gReports.create("OpenBTS.GSM.SMS.MTSMS.Start"); + // count of mobile-temrinated SMS deliveries completed (got RP-ACK) + gReports.create("OpenBTS.GSM.SMS.MTSMS.Complete"); + + // count of mobile-originated setup messages + gReports.create("OpenBTS.GSM.CC.MOC.Setup"); + // count of mobile-terminated setup messages + gReports.create("OpenBTS.GSM.CC.MTC.Setup"); + // count of mobile-terminated release messages + gReports.create("OpenBTS.GSM.CC.MTD.Release"); + // count of mobile-originated disconnect messages + gReports.create("OpenBTS.GSM.CC.MOD.Disconnect"); + // total number of minutes of carried calls + gReports.create("OpenBTS.GSM.CC.CallMinutes"); + + // count of CS (non-GPRS) channel assignments + gReports.create("OpenBTS.GSM.RR.ChannelAssignment"); + //gReports.create("OpenBTS.GSM.RR.ChannelRelease"); + // count of number of times the beacon was regenerated + gReports.create("OpenBTS.GSM.RR.BeaconRegenerated"); + // count of successful channel assignments + gReports.create("OpenBTS.GSM.RR.ChannelSiezed"); + //gReports.create("OpenBTS.GSM.RR.LinkFailure"); + //gReports.create("OpenBTS.GSM.RR.Paged.IMSI"); + //gReports.create("OpenBTS.GSM.RR.Paged.TMSI"); + //gReports.create("OpenBTS.GSM.RR.Handover.Inbound.Request"); + //gReports.create("OpenBTS.GSM.RR.Handover.Inbound.Accept"); + //gReports.create("OpenBTS.GSM.RR.Handover.Inbound.Success"); + //gReports.create("OpenBTS.GSM.RR.Handover.Outbound.Request"); + //gReports.create("OpenBTS.GSM.RR.Handover.Outbound.Accept"); + //gReports.create("OpenBTS.GSM.RR.Handover.Outbound.Success"); + // histogram of timing advance for accepted RACH bursts + gReports.create("OpenBTS.GSM.RR.RACH.TA.Accepted",0,63); + + //gReports.create("Transceiver.StaleBurst"); + //gReports.create("Transceiver.Command.Received"); + //gReports.create("OpenBTS.TRX.Command.Sent"); + //gReports.create("OpenBTS.TRX.Command.Failed"); + //gReports.create("OpenBTS.TRX.FailedStart"); + //gReports.create("OpenBTS.TRX.LostLink"); +} + + + + int main(int argc, char *argv[]) { // TODO: Properly parse and handle any arguments @@ -147,9 +289,15 @@ int main(int argc, char *argv[]) return 0; } + createStats(); + + gReports.incr("OpenBTS.Starts"); + int sock = socket(AF_UNIX,SOCK_DGRAM,0); if (sock<0) { - perror("opening cmd datagram socket"); + perror("creating CLI datagram socket"); + LOG(ALERT) << "cannot create socket for CLI"; + gReports.incr("OpenBTS.Exit.CLI.Socket"); exit(1); } @@ -358,6 +506,8 @@ int main(int argc, char *argv[]) strcpy(cmdSockName.sun_path,sockpath); if (bind(sock, (struct sockaddr *) &cmdSockName, sizeof(struct sockaddr_un))) { perror("binding name to cmd datagram socket"); + LOG(ALERT) << "cannot bind socket for CLI at " << sockpath; + gReports.incr("OpenBTS.Exit.CLI.Socket"); exit(1); } @@ -366,6 +516,7 @@ int main(int argc, char *argv[]) struct sockaddr_un source; socklen_t sourceSize = sizeof(source); int nread = recvfrom(sock,cmdbuf,sizeof(cmdbuf)-1,0,(struct sockaddr*)&source,&sourceSize); + gReports.incr("OpenBTS.CLI.Command"); cmdbuf[nread]='\0'; LOG(INFO) << "received command \"" << cmdbuf << "\" from " << source.sun_path; std::ostringstream sout; @@ -375,15 +526,18 @@ int main(int argc, char *argv[]) LOG(INFO) << "sending " << strlen(rsp) << "-char result to " << source.sun_path; if (sendto(sock,rsp,strlen(rsp)+1,0,(struct sockaddr*)&source,sourceSize)<0) { LOG(ERR) << "can't send CLI response to " << source.sun_path; + gReports.incr("OpenBTS.CLI.Command.ResponseFailure"); } // res<0 means to exit the application if (res<0) break; + gReports.incr("OpenBTS.Exit.Normal.CLI"); } } // try catch (ConfigurationTableKeyNotFound e) { LOG(EMERG) << "required configuration parameter " << e.key() << " not defined, aborting"; + gReports.incr("OpenBTS.Exit.Error.ConfigurationParamterNotFound"); } //if (gTransceiverPid) kill(gTransceiverPid, SIGKILL);