Viewfinders MC
Welcome, %1$s. Please login or register.
March 29, 2024, 03:46:54 am

:    
--VCMC Presents ISDE Qualifier Championship Jan 28-29 Gorman--Club play day, fun for all at Jenkins land February 18 & 19th--   Adventure Riders Anza Borrego Desert Dash February 25-26 Julian, CA -- Time to ride!!!



--
Lets Ride!!!!
20094 1915 190
: Joey Gardner
*
+  Viewfinders MC
|-+  Public Board Topics
| |-+  General Discussion
| | |-+  All set to have a fun week!
0 and 1 Guest are viewing this topic. « previous next »
: [1]
: All set to have a fun week!  ( 3807 )
Chris Cory - President 2012-14 -Life Memeber
Administrator

Offline Offline

: 1981


Wear the shield with pride!


« : July 30, 2012, 07:31:26 pm »

All set to have a fun week!  :o
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!  ;D
<
##########  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 >
« : July 30, 2012, 07:39:40 pm Chris Cory - President »

Chris Cory
Dez O555
GP O555
Enduro O555
Keith Jones - VP
Officer

Offline Offline

: 1398


« #1 : July 30, 2012, 09:37:12 pm »

DON"T ANSWER THE PHONE!!! Problem solved ??? Never understood calculus and word problems were never a favorite! Back to the CAN and STRING easier to TRACE ;D KJ
Brian Matthews
Viewfinder

Offline Offline

: 201


« #2 : July 31, 2012, 06:41:26 pm »

That was 5 seconds worth of data.  I bet a teenager in love phone call would cause a meltdown.
Bob Johnson - D37 Rep

Offline Offline

: 2459



« #3 : August 02, 2012, 11:10:56 am »

Can't understand any of it and don't really want to try  ;)

Mr J
R32 DEZ
RETIRED !!
Charlie & Darlene Barney - Life Members, 2015 President
Global Moderator

Offline Offline

: 1684



« #4 : August 02, 2012, 11:34:26 am »

What the hell it is this Chris?

CB

CB
2015 President & Big 6 Rep/ Life member/ Joined-1974.
Do you Bleed Golden Rod ?
Bill McInnes - D37 Rep
Reps

Offline Offline

: 151


« #5 : August 02, 2012, 01:48:17 pm »


 192.168.40.182 is placing the call and 192.168.40.18 is answering the call.
 All good stuff.

 Flat Tire
Donn Nay
Global Moderator

Offline Offline

: 3443


« #6 : August 03, 2012, 07:25:22 am »


 192.168.40.182 is placing the call and 192.168.40.18 is answering the call.
 All good stuff.

 Flat Tire

You guys talk funny!
Chris Cory - President 2012-14 -Life Memeber
Administrator

Offline Offline

: 1981


Wear the shield with pride!


« #7 : August 05, 2012, 02:53:07 pm »

CB, This is a packet trace on the network that shows what is happening on the network during a 5 sec call. Lots of stuff going on behind the scenes when you make a little phone call.  ;D

In real life, when I have done these captures, about one minute equaled around 10,000 lines of info like above.

Things have sure changed a lot since I started doing this in 98.

Chris Cory
Dez O555
GP O555
Enduro O555
: [1]  
« previous next »
:  

Powered by MySQL Powered by PHP SMF 2.0.9 | SMF © 2014, Simple Machines Valid XHTML 1.0! Valid CSS!