All set to have a fun week!
So I am in training all week and this is something that we went over today. This is a trace of a simple phone call that was answered and then hung up (a little over 5 seconds long). We are supposed to be able to go through this and follow the call flow. The #### sentences are added in to help explain what is going on but aren't in a real call trace.
I can't what for tomorrow!
<
########## Sample syslog file for Tel-->IP call on FXS gateway
10:33:54.703 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1966 ) recv <-- OFF_HOOK Ch:1
10:33:54.703 : 192.168.40.182 : NOTICE :( lgr_flow)(1967 ) #1:OFF_HOOK_EV
########## In a Tel-->IP call the ENDPOINT object is instantiated first.
########## The phone attached to the FXS on port 2 (Ch:1) has gone off hook.
########## Recall that syslog channels are zero-based, whereas the physical
########## ports are one-based counters.
########## The symbol '#1' in log 1967 is lined up against the left margin, so is
########## associated with the board/endpoint side of the call (phyiscal analog port)
########## therefore #1 (port2) is the endpoint object associated with the endpoint
########## layer object for this call flow.
10:33:54.703 : 192.168.40.182 : NOTICE :( lgr_flow)(1968 ) | #1:OFF_HOOK_EV
10:33:54.718 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1969 ) UpdateChannelParams, Channel 1
10:33:54.718 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1970 ) #1:ConfigFaxModemChannelParams NSEMode=0, CNGDetMode=0, FAXTranType=1, VxxTranType=2, VoiceVol= 1, DTMFVol=-11, InGain=0, RTPRedDepth=0, ECE=1, SCE=0, ECNlpMode=0, DJBufMinDelay=10, DJBufOptFac=10)
10:33:54.718 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1971 ) ActivateDigitMap for channel : 1, MaxDialStringLength = 9, MaxEndDialTimer = 4000, MaxLongInterDigitTimer = 8000, MaxStartTimer = 16000, DigitMap = [0-9*#ABCD][0-9ABCD].T|*77|*55
10:33:54.718 : 192.168.40.182 : NOTICE :( lgr_flow)(1972 ) #-100: StartDigitMapDetection with params: <Pattern=[0-9*#ABCD][0-9ABCD].T|*77|*55>
<MaxStartTimer=16000>
<SendEachDigit=1>
<UseEndDialKey=0>
<MaxLongInterDigitTimer=8000>
<MaxEndDialTimer=4000>
<MaxDialStringLength=9>
<MaxShortInterDigitTimer=0>
<MinInterDigitLen=-2>
<MinDigitLen=-2>
<EndDialWithHashMark=0>
10:33:54.750 : 192.168.40.182 : NOTICE :(lgr_digitmap_mngr)(1973 ) #1:Activate DigitMapMngr pattern:[0-9*#ABCD][0-9ABCD].T|*77|*55 ,Max Length is: 9
10:33:54.750 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1974 ) Changed ECNlpMOde to: 1
10:33:54.750 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1975 ) #1:PSOSBoardInterface::PlayTone - Called Tone=DIAL_TONE Direction=PLAY_TONE_2_TEL
10:33:55.593 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1976 ) recv <-- DIGIT(8) Ch:1 OnTime:0 InterTime:1094325 Direction:0 System:1
10:33:55.593 : 192.168.40.182 : NOTICE :( lgr_flow)(1977 ) #1:DIGIT_EV
10:33:55.609 : 192.168.40.182 : NOTICE :( lgr_flow)(1978 ) | #1:DIGIT_EV
10:33:55.609 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(1979 ) #1:PSOSBoardInterface::StopPlayTone- Called
10:33:55.687 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1980 ) recv <-- DIGIT(8) Ch:1 OnTime:80 InterTime:1094325 Direction:0 System:1
10:33:55.703 : 192.168.40.182 : NOTICE :( lgr_flow)(1981 ) #1:DIGIT_EV
10:33:55.703 : 192.168.40.182 : NOTICE :( lgr_flow)(1982 ) | #1:DIGIT_EV
10:33:55.765 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1983 ) recv <-- DIGIT(0) Ch:1 OnTime:0 InterTime:100 Direction:0 System:1
10:33:55.781 : 192.168.40.182 : NOTICE :( lgr_flow)(1984 ) #1:DIGIT_EV
10:33:55.781 : 192.168.40.182 : NOTICE :( lgr_flow)(1985 ) | #1:DIGIT_EV
10:33:55.859 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1986 ) recv <-- DIGIT(0) Ch:1 OnTime:80 InterTime:100 Direction:0 System:1
10:33:55.875 : 192.168.40.182 : NOTICE :( lgr_flow)(1987 ) #1:DIGIT_EV
10:33:55.875 : 192.168.40.182 : NOTICE :( lgr_flow)(1988 ) | #1:DIGIT_EV
10:33:56.031 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1989 ) recv <-- DIGIT(1) Ch:1 OnTime:0 InterTime:180 Direction:0 System:1
10:33:56.046 : 192.168.40.182 : NOTICE :( lgr_flow)(1990 ) #1:DIGIT_EV
10:33:56.046 : 192.168.40.182 : NOTICE :( lgr_flow)(1991 ) | #1:DIGIT_EV
10:33:56.125 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1992 ) recv <-- DIGIT(1) Ch:1 OnTime:80 InterTime:180 Direction:0 System:1
10:33:56.125 : 192.168.40.182 : NOTICE :( lgr_flow)(1993 ) #1:DIGIT_EV
10:33:56.125 : 192.168.40.182 : NOTICE :( lgr_flow)(1994 ) | #1:DIGIT_EV
10:33:56.406 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1995 ) recv <-- DIGIT(1) Ch:1 OnTime:0 InterTime:290 Direction:0 System:1
10:33:56.421 : 192.168.40.182 : NOTICE :( lgr_flow)(1996 ) #1:DIGIT_EV
10:33:56.421 : 192.168.40.182 : NOTICE :( lgr_flow)(1997 ) | #1:DIGIT_EV
10:33:56.500 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(1998 ) recv <-- DIGIT(1) Ch:1 OnTime:90 InterTime:290 Direction:0 System:1
10:33:56.531 : 192.168.40.182 : NOTICE :( lgr_flow)(1999 ) #1:DIGIT_EV
10:33:56.531 : 192.168.40.182 : NOTICE :( lgr_flow)(2000 ) | #1:DIGIT_EV
10:33:56.718 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2001 ) recv <-- DIGIT(0) Ch:1 OnTime:0 InterTime:230 Direction:0 System:1
10:33:56.734 : 192.168.40.182 : NOTICE :( lgr_flow)(2002 ) #1:DIGIT_EV
10:33:56.734 : 192.168.40.182 : NOTICE :( lgr_flow)(2003 ) | #1:DIGIT_EV
10:33:56.796 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2004 ) recv <-- DIGIT(0) Ch:1 OnTime:70 InterTime:230 Direction:0 System:1
10:33:56.828 : 192.168.40.182 : NOTICE :( lgr_flow)(2005 ) #1:DIGIT_EV
10:33:56.828 : 192.168.40.182 : NOTICE :( lgr_flow)(2006 ) | #1:DIGIT_EV
10:33:56.890 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2007 ) recv <-- DIGIT(0) Ch:1 OnTime:0 InterTime:100 Direction:0 System:1
10:33:56.906 : 192.168.40.182 : NOTICE :( lgr_flow)(2008 ) #1:DIGIT_EV
10:33:56.906 : 192.168.40.182 : NOTICE :( lgr_flow)(2009 ) | #1:DIGIT_EV
10:33:56.984 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2010 ) recv <-- DIGIT(0) Ch:1 OnTime:90 InterTime:100 Direction:0 System:1
10:33:57.000 : 192.168.40.182 : NOTICE :( lgr_flow)(2011 ) #1:DIGIT_EV
10:33:57.000 : 192.168.40.182 : NOTICE :( lgr_flow)(2012 ) | #1:DIGIT_EV
10:33:57.125 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2013 ) recv <-- DIGIT(1) Ch:1 OnTime:0 InterTime:140 Direction:0 System:1
10:33:57.125 : 192.168.40.182 : NOTICE :( lgr_flow)(2014 ) #1:DIGIT_EV
10:33:57.140 : 192.168.40.182 : NOTICE :( lgr_flow)(2015 ) | #1:DIGIT_EV
10:33:57.218 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2016 ) recv <-- DIGIT(1) Ch:1 OnTime:80 InterTime:140 Direction:0 System:1
10:33:57.218 : 192.168.40.182 : NOTICE :( lgr_flow)(2017 ) #1:DIGIT_EV
10:33:57.234 : 192.168.40.182 : NOTICE :( lgr_flow)(2018 ) | #1:DIGIT_EV
10:33:57.421 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2019 ) recv <-- DIGIT(11) Ch:1 OnTime:0 InterTime:220 Direction:0 System:1
10:33:57.421 : 192.168.40.182 : NOTICE :( lgr_flow)(2020 ) #1:DIGIT_EV
10:33:57.437 : 192.168.40.182 : NOTICE :( lgr_flow)(2021 ) | #1:DIGIT_EV
10:33:57.515 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2022 ) recv <-- EV_DIALED_STRING Ch:1 Str:8011001 MapNum:0 CM:FM Match:1 EI:#
10:33:57.531 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2023 ) recv <-- DIGIT(11) Ch:1 OnTime:80 InterTime:220 Direction:0 System:1
10:33:57.531 : 192.168.40.182 : NOTICE :( lgr_flow)(2024 ) #1:DIALED_STRING_EV
10:33:57.546 : 192.168.40.182 : NOTICE :( lgr_flow)(2025 ) | #1:DIALED_STRING_EV
10:33:57.546 : 192.168.40.182 : NOTICE :(lgr_digitmap_mngr)(2026 ) DigitMapMngr::HandleDialStringEv Match = 1, MatchNum = 0 STR = 8011001
########## Up until log 2026 the Endpoint layer is the only entity involved in the call
########## as the gateway is in digit collectoin mode on the Tel side. Once a dialed digit
########## string is reached the gateay invokes the CALL layer. Log 2028 shows the ENDPOINT
########## layer invoking the CALL layer. #89 is allocated in log 2029 for the call layer.
########## From this point on both the ENDPOINT #1 and CALL #89 are associated with each other
########## until the call is terminated.
10:33:57.562 : 192.168.40.182 : NOTICE :( lgr_callf)(2027 ) new Call created - #89
10:33:57.562 : 192.168.40.182 : NOTICE :( lgr_flow)(2028 ) | #1:NEW_CALL_EV (send) : (UnKnown)
10:33:57.578 : 192.168.40.182 : NOTICE :( lgr_flow)(2029 ) | | #89:NEW_CALL_EV:(UnKnown)
10:33:57.578 : 192.168.40.182 : NOTICE :( lgr_stk_mngr)(2030 ) Resource StackSession <#89> Allocated
10:33:57.578 : 192.168.40.182 : NOTICE :( lgr_flow)(2031 ) | | #89:Call changing states from:IdleState to:NewCallState_Tel2IP
10:33:57.593 : 192.168.40.182 : NOTICE :( lgr_flow)(2032 ) | | | #89:NEW_CALL_EV(UNKnown)
10:33:57.593 : 192.168.40.182 : NOTICE :( lgr_call)(2033 ) | | #89GetNextUI:GlobalUI=1491907432, mACAddrLsb=836360
10:33:57.609 : 192.168.40.182 : NOTICE :( lgr_call)(2034 ) | | #89GetNextUI:GlobalUI=1491907433
10:33:57.609 : 192.168.40.182 : NOTICE :( lgr_flow)(2035 ) | (to 8011001)
10:33:57.625 : 192.168.40.182 : NOTICE :( lgr_flow)(2036 ) | #1:SETUP (send) : (UnKnown)
10:33:57.625 : 192.168.40.182 : NOTICE :( lgr_flow)(2037 ) | | #89:SETUP (TO:8011001, FROM:8011002):(UnKnown)
10:33:57.625 : 192.168.40.182 : NOTICE :( lgr_call)(2038 ) new call from EndPoint
10:33:57.640 : 192.168.40.182 : NOTICE :( lgr_flow)(2039 ) | | #89:Call changing states from:NewCallState_Tel2IP to:InitiatedState_Tel2IP
10:33:57.640 : 192.168.40.182 : NOTICE :( lgr_flow)(2040 ) | | | #89:SETUP(UNKnown)
10:33:57.656 : 192.168.40.182 : NOTICE :( lgr_stack)(2041 ) FindIpDestination: rmRc:0 (OK) SrcIpGroup:-1 IpconnHndl:-1 DstPrefix:8011001 DstIp:10.15.3.11
10:33:57.656 : 192.168.40.182 : NOTICE :( lgr_stack)(2042 ) RoutingInstance (#89) RouteToProxyIfExists: find route to proxy DestIPGroup 0
10:33:57.671 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2043 ) <SESSION #89> UpdateAfterDecidingRouting: IpProfileId (0), ChargeCode (255), NewIndex (-100)
10:33:57.671 : 192.168.40.182 : NOTICE :( lgr_call)(2044 ) Call::SetCoderListForCall #89 Found 1 Common Coders For Call
10:33:57.671 : 192.168.40.182 : NOTICE :( lgr_call)(2045 ) <Call #89> Coder g711Ulaw64k20 : 20
10:33:57.687 : 192.168.40.182 : NOTICE :( lgr_profiling)(2046 ) <Call 89> Profiled<Tel=0,Ip=0>: JBMinDel=10 JBOptF=10 EEarlyM=1 FaxTM=1 IPDS=46 IsFaxU=1 PI2IP=-1 SigIPDF=40 CNGMode=0 DTMFUsed=0 NSEMode=0 PlayRBTone2IP=0 RBUdpPort=0 RTPRD=0 SCE=0 VxxTT=2 Dst2Rdrt=0 DTMFVol=20 ECE=1 ECurDis=0 EDigDel=0 ERevP=0 FHPer=700 InG=32 MWIA=0 MWID=0 VVol=33 ReorderTime=5
########## The CALL layer #89 handled all manipulation and routing decisions after its inception
########## up until log 2046. At this point the CALL layer needs to involve the SIP stack to
########## send the call out the IP side of the gateway. Log 2047 shows the SIP STACKSESSION
########## layer being invoked and associated with CALL object #89. In log 2048 the SIP STACKSESSION
########## is given #113 as the object identifier for the duration of the call. At this point all
########## 3 of the core objects have been created (ENDPOINT #1, CALL #89, and SIP #113) and logically
########## associated with each other. All logs referencing those objects until call termination
########## indicate logs associaetd with the call flow for that call.
10:33:57.687 : 192.168.40.182 : NOTICE :( sip_stack)(2047 ) new AcSIPCallAPI created - #89
10:33:57.687 : 192.168.40.182 : NOTICE :( lgr_flow)(2048 ) | | new GetNewSIPCall created - #113
10:33:57.703 : 192.168.40.182 : NOTICE :( sip_stack)(2049 ) SIPSDPSession#89 - Changing state from SIP_MEDIA_IDLE to SIP_MEDIA_OFFERING
10:33:57.703 : 192.168.40.182 : NOTICE :( lgr_flow)(2050 ) | |(SIPTU#113)SETUP_REQ State:Idle()
10:33:57.718 : 192.168.40.182 : NOTICE :( sip_stack)(2051 ) SIPCall(#113) changes state from Idle to Inviting
10:33:57.718 : 192.168.40.182 : NOTICE :( lgr_flow)(2052 ) ---- Outgoing SIP Message to 192.168.40.18:5060 ----
########## After the SIP message is created and sent the SIP Call-ID can be used
########## as something to search for as the objects will reference it going forward.
10:33:57.718 : 192.168.40.182 : NOTICE : INVITE sip:8011001@training.audiocodes.com;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1027131136
Max-Forwards: 70
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>
Call-ID:
102711383611200004037@192.168.40.182 CSeq: 1 INVITE
Contact: <sip:8011002@192.168.40.182>
Supported: em,100rel,timer,replaces,path,early-session,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
User-Agent: Audiocodes-Sip-Gateway-Mediant 1000/v.5.40A.029
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 272
v=0
o=AudiocodesGW 1027098112 1027097810 IN IP4 192.168.40.182
s=Phone-Call
c=IN IP4 192.168.40.182
t=0 0
m=audio 6010 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
a=rtcp:6011 IN IP4 192.168.40.182
10:33:57.765 : 192.168.40.182 : NOTICE :( sip_stack)(2054 ) UdpRtxMngr::Transmit 1 INVITE Rtx Left: 6 Dest: 192.168.40.18:5060 CallID: (
102711383611200004037@192.168.40.182)
10:33:57.796 : 192.168.40.182 : NOTICE :( lgr_flow)(2055 ) #1:DIGIT_EV
10:33:57.796 : 192.168.40.182 : NOTICE :( lgr_flow)(2056 ) | #1:DIGIT_EV
########## Note that #1 references the SIP Call-ID from the message in log 2052 which was created
########## and sent by SIP STACKSESSION object #113, which we know is related to #1.
10:33:57.796 : 192.168.40.182 : NOTICE :( lgr_flow)(2057 ) | #1:DTMF (send) : (
102711383611200004037@192.168.40.182)
########## Note that #89 references the SIP Call-ID from the message in log 2052 which was created
########## and sent by SIP STACKSESSION object #113, which we know is related to #89.
10:33:57.812 : 192.168.40.182 : NOTICE :( lgr_flow)(2058 ) | | #89:DTMF:(
102711383611200004037@192.168.40.182)
10:33:57.812 : 192.168.40.182 : NOTICE :( lgr_flow)(2059 ) | | | #89:DTMF(
102711383611200004037@192.168.40.182)
10:33:57.812 : 192.168.40.182 : NOTICE :( lgr_flow)(2060 ) ---- Incoming SIP Message from 192.168.40.18:32775 ----
10:33:57.812 : 192.168.40.182 : NOTICE : SIP/2.0 100 Trying
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>
Call-Id:
102711383611200004037@192.168.40.182 Cseq: 1 INVITE
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1027131136
Content-Length: 0
10:33:57.828 : 192.168.40.182 : NOTICE :( sip_stack)(2062 ) UdpRtxMngr::Remove 1 INVITE
10:33:57.843 : 192.168.40.182 : NOTICE :( lgr_flow)(2063 ) | |(SIPTU#113)100 State:Inviting(
102711383611200004037@192.168.40.182)
10:33:57.843 : 192.168.40.182 : NOTICE :( sip_stack)(2064 ) SIPCall(#113) changes state from Inviting to Proceeding
10:33:57.859 : 192.168.40.182 : NOTICE :( lgr_flow)(2065 ) | | | #89:SIP_TRYING_EV(
102711383611200004037@192.168.40.182)
10:33:57.859 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2066 ) <SESSION #89> SendToCall - event: PROCEEDING m_Call = 106258024
10:33:57.859 : 192.168.40.182 : NOTICE :( lgr_flow)(2067 ) | | #89:PROCEEDING:(
102711383611200004037@192.168.40.182)
10:33:57.859 : 192.168.40.182 : NOTICE :( lgr_flow)(2068 ) | #1:PROCEEDING : (
102711383611200004037@192.168.40.182)
10:33:57.968 : 192.168.40.182 : NOTICE :( lgr_flow)(2069 ) ---- Incoming SIP Message from 192.168.40.18:32775 ----
10:33:57.984 : 192.168.40.182 : NOTICE : SIP/2.0 180 Ringing
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>;tag=264539308
Call-Id:
102711383611200004037@192.168.40.182 Cseq: 1 INVITE
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1027131136
Date: Tue, 04 Nov 2008 10:34:25 GMT
Contact: sip:192.168.40.18:5100
User-Agent: sipX/3.8.1 sipX/vxml (Linux)
Accept-Language: en
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY
Supported: sip-cc, sip-cc-01, replaces, replaces
Content-Length: 0
10:33:58.000 : 192.168.40.182 : NOTICE :( lgr_flow)(2071 ) | |(SIPTU#113)180 State:Proceeding(
102711383611200004037@192.168.40.182)
10:33:58.015 : 192.168.40.182 : NOTICE :( lgr_flow)(2072 ) | | | #89:SIP_ALERT_EV(
102711383611200004037@192.168.40.182)
10:33:58.031 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2073 ) <SESSION #89> SendToCall - event: PROGRESS_INDICATOR_EV m_Call = 106258024
10:33:58.031 : 192.168.40.182 : NOTICE :( lgr_flow)(2074 ) | | #89:PROGRESS_INDICATOR_EV(PI=-1)(PC=-1):(
102711383611200004037@192.168.40.182)
10:33:58.046 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2075 ) <SESSION #89> SendToCall - event: ALERT m_Call = 106258024
10:33:58.046 : 192.168.40.182 : NOTICE :( lgr_flow)(2076 ) | | #89:ALERT:(
102711383611200004037@192.168.40.182)
10:33:58.046 : 192.168.40.182 : NOTICE :( lgr_flow)(2077 ) | | #89:Call changing states from:InitiatedState_Tel2IP to:AlertingState_Tel2IP
10:33:58.062 : 192.168.40.182 : NOTICE :( lgr_flow)(2078 ) | #1:ALERT : (
102711383611200004037@192.168.40.182)
10:33:58.062 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2079 ) #1:PSOSBoardInterface::PlayTone - Called Tone=RINGBACK_TONE Direction=PLAY_TONE_2_TEL
10:33:58.062 : 192.168.40.182 : NOTICE :( lgr_flow)(2080 ) | |(SIPTU#113)PRACK_REQ State:Proceeding(
102711383611200004037@192.168.40.182)
10:33:58.078 : 192.168.40.182 : NOTICE :( lgr_flow)(2081 ) ---- Incoming SIP Message from 192.168.40.18:32775 ----
10:33:58.078 : 192.168.40.182 : NOTICE : SIP/2.0 200 OK
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>;tag=264539308
Call-Id:
102711383611200004037@192.168.40.182 Cseq: 1 INVITE
Contact: sip:192.168.40.18:5100
Content-Type: application/sdp
Content-Length: 172
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1027131136
Record-Route: <sip:192.168.40.18:5080;lr;sipX-route=%2Afrom%7EMWMxMDI3MTE0Nzcy.authrules%2Aauth%7E%21457843309476bcb19427db375318fc80>
Date: Tue, 04 Nov 2008 10:34:25 GMT
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY
User-Agent: sipX/3.8.1 sipX/vxml (Linux)
Accept-Language: en
Supported: sip-cc, sip-cc-01, replaces, replaces
v=0
o=sipX 5 6 IN IP4 192.168.40.18
s=phone-call
c=IN IP4 192.168.40.18
t=0 0
m=audio 9000 RTP/AVP 0 101
a=rtpmap:0 pcmu/8000/1
a=rtpmap:101 telephone-event/8000/1
10:33:58.125 : 192.168.40.182 : NOTICE :( lgr_flow)(2083 ) | |(SIPTU#113)200 OK State:Proceeding(
102711383611200004037@192.168.40.182)
10:33:58.140 : 192.168.40.182 : NOTICE :( sip_stack)(2084 ) SIPCall(#113) changes state from Proceeding to RemoteAccepted
10:33:58.140 : 192.168.40.182 : NOTICE :( lgr_flow)(2085 ) | | | #89:SIP_CONNECT_EV(
102711383611200004037@192.168.40.182)
10:33:58.140 : 192.168.40.182 : NOTICE :( sip_stack)(2086 ) SIPSDPSession#89 - Changing state from SIP_MEDIA_OFFERING to SIP_MEDIA_COMPLETED
10:33:58.156 : 192.168.40.182 : NOTICE :( lgr_flow)(2087 ) | |(SIPTU#113)ACK_REQ State:RemoteAccepted(
102711383611200004037@192.168.40.182)
10:33:58.156 : 192.168.40.182 : NOTICE :( sip_stack)(2088 ) SIPCall(#113) changes state from RemoteAccepted to Connected
10:33:58.156 : 192.168.40.182 : NOTICE :( lgr_flow)(2089 ) ---- Outgoing SIP Message to 192.168.40.18:5080 ----
10:33:58.171 : 192.168.40.182 : NOTICE : ACK sip:192.168.40.18:5100 SIP/2.0
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1034547359
Max-Forwards: 70
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>;tag=264539308
Call-ID:
102711383611200004037@192.168.40.182 CSeq: 1 ACK
Contact: <sip:8011002@192.168.40.182>
Route: <sip:192.168.40.18:5080;lr;sipX-route=%2Afrom%7EMWMxMDI3MTE0Nzcy.authrules%2Aauth%7E%21457843309476bcb19427db375318fc80>
Supported: em,timer,replaces,path,early-session,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
User-Agent: Audiocodes-Sip-Gateway-Mediant 1000/v.5.40A.029
Content-Length: 0
10:33:58.187 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2091 ) DtmfCapNegotiationAlgorithm :: TxDtmfMethod = DTMF_RFC2833_SUPPORTED
10:33:58.203 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2092 ) DtmfCapNegotiationAlgorithm :: TxRtpRfc2833Payload = 101
10:33:58.203 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2093 ) <SESSION #89> SendToCall - event: DTMF_CONTROL_EV m_Call = 106258024
10:33:58.203 : 192.168.40.182 : NOTICE :( lgr_flow)(2094 ) | | #89:DTMF_CONTROL_EV:(
102711383611200004037@192.168.40.182)
10:33:58.218 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2095 ) <SESSION #89> SendToCall - event: OPEN_LOGICAL_CHANNEL_ACK m_Call = 106258024
10:33:58.218 : 192.168.40.182 : NOTICE :( lgr_flow)(2096 ) | | #89:OPEN_LOGICAL_CHANNEL_ACK:(
102711383611200004037@192.168.40.182)
10:33:58.234 : 192.168.40.182 : NOTICE :( lgr_flow)(2097 ) | #1:OPEN_LOGICAL_CHANNEL_ACK : (
102711383611200004037@192.168.40.182)
10:33:58.234 : 192.168.40.182 : NOTICE :( lgr_flow)(2098 ) | #1:OPEN_VOICE (IP:c0a82812, RTP:9000, RTCP:9001, VoiceCoder:g711Ulaw64k20, VbdCoder: InvalidCoder255, Dtmf:gwRFC2833RalayDTMF,Rx payload:101,Tx payload:101 ,RTPmode:1, FaxTransportType: 1,AVoIPMediaType: gwMediaTypeAudioOnly)
10:33:58.234 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2099 ) #1:ActivateChannel: Socks=14 CID=1 Trunk:-1 BChannel:1 RemoteIP=20b93a0 RemotePort=9000 RemoteRTCPIP=20b93b4 RemoteRTCPPort=9001 FaxModemDet=NO_FAX_MODEM_DETECTED
10:33:58.250 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2100 ) Open channel: IsVoiceOn: 1, IsT38On: 0, IsVbdOn: 0, IsVideoOn: 0
10:33:58.250 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2101 ) #1:OpenChannel:on Trunk -1 BChannel:1 CID=1 with VoiceCoder: g711Ulaw64k20 VbdCoder: InvalidCoder255 DetectorSide: 0 FaxModemDet NO_FAX_MODEM_DETECTED
10:33:58.250 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2102 ) #1:OpenChannel VoiceVolume= 1, DTMFVolume = -11, InputGain = 0, RTPRedundancyDepth = 0 FlashHookPeriod = 700 AgcCmd = 0x13180000
10:33:58.265 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2103 ) OpenChannel, CoderType = 1, Interval = 3, M = 1
10:33:58.265 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2104 ) #1:FAXTransportType = 1
10:33:58.281 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2105 ) #1:ConfigFaxModemChannelParams NSEMode=0, CNGDetMode=0, FAXTranType=1, VxxTranType=2, VoiceVol= 1, DTMFVol=-11, InGain=0, RTPRedDepth=0, ECE=1, SCE=0, ECNlpMode=0, DJBufMinDelay=10, DJBufOptFac=10)
10:33:58.281 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2106 ) Detectors: Amd:0, Ans:0 En:0 IBScmd:0xa1
10:33:58.281 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2107 ) Setting ActivateRTP_RTCPCmd.Cmd.IpTosFieldInUdpPacket to 184
10:33:58.296 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2108 ) #1:ActivateChannel:RtpPayload: 0
10:33:58.296 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2109 ) #1:PSOSBoardInterface::PlayTone - Called Tone=RINGBACK_TONE Direction=PLAY_TONE_2_TEL
10:33:58.296 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2110 ) <SESSION #89> SendToCall - event: CONNECT m_Call = 106258024
10:33:58.312 : 192.168.40.182 : NOTICE :( lgr_flow)(2111 ) | | #89:CONNECT:(
102711383611200004037@192.168.40.182)
10:33:58.312 : 192.168.40.182 : NOTICE :( lgr_flow)(2112 ) | | #89:Call changing states from:AlertingState_Tel2IP to:ConnectedState
10:33:58.312 : 192.168.40.182 : NOTICE :( lgr_flow)(2113 ) | #1:CONNECT : (
102711383611200004037@192.168.40.182)
10:33:58.328 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2114 ) Restart ECE control (CID=1)
10:33:58.328 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2115 ) #1:PSOSBoardInterface::StopPlayTone- Called
10:33:58.343 : 192.168.40.182 : NOTICE :( lgr_flow)(2116 ) #1:LOCAL_END_PLAYING_CALL_PROGRESS_TONE_EV
10:33:58.343 : 192.168.40.182 : NOTICE :( lgr_flow)(2117 ) | #1:LOCAL_END_PLAYING_CALL_PROGRESS_TONE_EV
########## The remaining logs beginning with log 2118 analyze the tearing down
########## of the various objects associated with the call relating to #1, #89 and #113
########## In log 2118 Ch:1 (ie #1) goes ON_HOOK
10:34:02.953 : 192.168.40.182 : NOTICE :( lgr_psbrdex)(2118 ) recv <-- ON_HOOK Ch:1
10:34:02.953 : 192.168.40.182 : NOTICE :( lgr_flow)(2119 ) #1:ON_HOOK_EV
10:34:02.968 : 192.168.40.182 : NOTICE :( lgr_flow)(2120 ) | #1:ON_HOOK_EV
10:34:02.968 : 192.168.40.182 : NOTICE :( lgr_flow)(2121 ) | #1:Close voice Channel
10:34:02.968 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2122 ) #1:StopRTP_RTCP on channel 1
########## #1 has begun the process of tearing the call down by closine the voice channel
########## and stopping RTP and RTCP on channel 1.
########## At this point #1 sends a RELEASE with cause code GWAPP_NORMAL_CALL_CLEAR
########## to the CALL layer #89 to pass along the notification that the call is
########## being terminated.
10:34:02.984 : 192.168.40.182 : NOTICE :( lgr_flow)(2123 ) | #1:RELEASE (send) GWAPP_NORMAL_CALL_CLEAR : (
102711383611200004037@192.168.40.182)
10:34:02.984 : 192.168.40.182 : NOTICE :( lgr_flow)(2124 ) | | #89:RELEASE:(
102711383611200004037@192.168.40.182)
10:34:03.000 : 192.168.40.182 : NOTICE :( lgr_flow)(2125 ) | | #89:Call changing states from:ConnectedState to:DisconnectingState
########## #89 sends the termination event up to the SIP STACKSESSION layer in log 2127
10:34:03.000 : 192.168.40.182 : NOTICE :( lgr_flow)(2126 ) | | #89:RELEASE_ACK:(
102711383611200004037@192.168.40.182)
10:34:03.015 : 192.168.40.182 : NOTICE :( lgr_flow)(2127 ) | | | #89:RELEASE(
102711383611200004037@192.168.40.182)
########## As a result of recieving notification of call termination from the ENDPOINT layer
########## the SIP STACKSESSION initiates the BYE request to the remote side IP entity
10:34:03.031 : 192.168.40.182 : NOTICE :( lgr_flow)(2128 ) | |(SIPTU#113)DISCONNECT_REQ State:Connected(
102711383611200004037@192.168.40.182)
10:34:03.031 : 192.168.40.182 : NOTICE :( lgr_flow)(2129 ) ---- Outgoing SIP Message to 192.168.40.18:5080 ----
10:34:03.031 : 192.168.40.182 : NOTICE : BYE sip:192.168.40.18:5100 SIP/2.0
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1116603309
Max-Forwards: 70
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>;tag=264539308
Call-ID:
102711383611200004037@192.168.40.182 CSeq: 2 BYE
Route: <sip:192.168.40.18:5080;lr;sipX-route=%2Afrom%7EMWMxMDI3MTE0Nzcy.authrules%2Aauth%7E%21457843309476bcb19427db375318fc80>
Supported: em,timer,replaces,path,early-session,resource-priority
Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE
User-Agent: Audiocodes-Sip-Gateway-Mediant 1000/v.5.40A.029
Reason: Q.850 ;cause=16
Content-Length: 0
10:34:03.078 : 192.168.40.182 : NOTICE :( sip_stack)(2131 ) UdpRtxMngr::Transmit 2 BYE Rtx Left: 6 Dest: 192.168.40.18:5080 CallID: (
102711383611200004037@192.168.40.182)
10:34:03.093 : 192.168.40.182 : NOTICE :( sip_stack)(2132 ) SIPCall(#113) changes state from Connected to Disconnected
10:34:03.093 : 192.168.40.182 : NOTICE :( lgr_stk_ses)(2133 ) <SESSION #89> SendToCall - event: RELEASE_ACK m_Call = 106258024
10:34:03.093 : 192.168.40.182 : NOTICE :( lgr_flow)(2134 ) | | #89:RELEASE_ACK:(
102711383611200004037@192.168.40.182)
########## The CALL layer is no longer needed. Both the ENDPOINT and STACKSESSION layers
########## are handling their respective disconnect operatoins and is deleted in log 2135
########## Logs 2136 to 2138 show the disassocaition of the SIP object #113 from the deleted
########## CALL layer
10:34:03.109 : 192.168.40.182 : NOTICE :( lgr_callf)(2135 ) Call #89 deleted
10:34:03.109 : 192.168.40.182 : NOTICE :( sip_stack)(2136 ) AcSIPStackAPI::FreeCallAPI - #89
10:34:03.109 : 192.168.40.182 : NOTICE :( sip_stack)(2137 ) Setting ApplicationCall of AcSIPCall #113 to NULL
10:34:03.125 : 192.168.40.182 : NOTICE :( lgr_stk_mngr)(2138 ) Resource StackSession <#89> Deleted
########## The ENDPOINT layer goes about cleaning up its resource and setting the channel
########## paramters back to the ENDPOINT default settings for the current configuration
########## in logs 2139 to 2147
10:34:03.125 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2139 ) #1:PSOSBoardInterface::StopPlayTone- Called
10:34:03.140 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2140 ) #1:cpDigitMapHndlr_Stop - Stoped (0)
10:34:03.140 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2141 ) #1:CloseChannel: ChannelNum=1
10:34:03.140 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2142 ) Open channel: IsVoiceOn: 1, IsT38On: 0, IsVbdOn: 0, IsVideoOn: 0
10:34:03.156 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2143 ) #1:OpenChannel:on Trunk -1 BChannel:1 CID=1 with VoiceCoder: g711Ulaw64k20 VbdCoder: InvalidCoder255 DetectorSide: 0 FaxModemDet NO_FAX_MODEM_DETECTED
10:34:03.156 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2144 ) #1:OpenChannel VoiceVolume= 1, DTMFVolume = -11, InputGain = 0, RTPRedundancyDepth = 0 FlashHookPeriod = 700 AgcCmd = 0x13180000
10:34:03.156 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2145 ) OpenChannel, CoderType = 1, Interval = 3, M = 1
10:34:03.156 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2146 ) #1:FAXTransportType = 1
10:34:03.171 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2147 ) #1:ConfigFaxModemChannelParams NSEMode=0, CNGDetMode=0, FAXTranType=1, VxxTranType=2, VoiceVol= 1, DTMFVol=-11, InGain=0, RTPRedDepth=0, ECE=1, SCE=0, ECNlpMode=0, DJBufMinDelay=10, DJBufOptFac=10)
10:34:03.171 : 192.168.40.182 : NOTICE :( lgr_psbrdif)(2148 ) Detectors: Amd:0, Ans:0 En:0 IBScmd:0xa1
10:34:03.171 : 192.168.40.182 : NOTICE :( lgr_flow)(2149 ) ---- Incoming SIP Message from 192.168.40.18:32783 ----
10:34:03.187 : 192.168.40.182 : NOTICE : SIP/2.0 200 OK
From: <sip:8011002@training.audiocodes.com>;tag=1c1027114772
To: <sip:8011001@training.audiocodes.com;user=phone>;tag=264539308
Call-Id:
102711383611200004037@192.168.40.182 Cseq: 2 BYE
Contact: sip:192.168.40.18:5100
Via: SIP/2.0/UDP 192.168.40.182;branch=z9hG4bKac1116603309
Date: Tue, 04 Nov 2008 10:34:30 GMT
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY
User-Agent: sipX/3.8.1 sipX/vxml (Linux)
Accept-Language: en
Supported: sip-cc, sip-cc-01, replaces, replaces
Content-Length: 0
########## The SIP STACKSESSION #113 receives the 200 OK to the BYE sent in log 2129.
########## #113 is then returned to the SIP resource pool
10:34:03.203 : 192.168.40.182 : NOTICE :( lgr_flow)(2151 ) | |(SIPTU#113)200 OK State:Disconnected(
102711383611200004037@192.168.40.182)
10:34:03.218 : 192.168.40.182 : NOTICE :( sip_stack)(2152 ) UdpRtxMngr::Remove 2 BYE
10:34:03.218 : 192.168.40.182 : NOTICE :( lgr_flow)(2153 ) | | TransactionUserMngr::ReturnSIPCall - #113
10:34:03.218 : 192.168.40.182 : NOTICE :( sip_stack)(2154 ) SIPCall(#113) changes state from Disconnected to Idle >