Support Support Downloads Knowledge Base Case Manager My Juniper Community

Knowledge Base

Search our Knowledge Base sites to find answers to your questions.

Ask All Knowledge Base Sites All Knowledge Base Sites JunosE Defect (KA)Knowledge BaseSecurity AdvisoriesTechnical BulletinsTechnotes Sign in to display secure content and recently viewed articles

[ScreenOS] Understanding the sip call flow through 'debug sip all'

0

0
Article ID: KB22365 KB Last Updated: 05 Jan 2012Version: 1.0 Summary:
This article provides information on how to understand the sip call flow via 'debug sip all'.
Symptoms:
Understanding the flow of Sip call and different messages involved in debug sip all.


Network:

172.16.8.3(Ip-phone) ----Switch----Firewall (eth0/7--untrust) 172.18.1.114----------Internet (172.16.144.201)
|
|
Sip Server (172.16.8.21)

172.16.144.201 — is the sip gateway which needs to be contacted to route the call.

Cause:

Solution:
In the output of debug sip all, debug rm all, and debug nat gate, the packet flow is:

  1. The firewall receives an invite packet from the 172.16.8.3 IP phone.

  2. After the packet is permitted by the policy, the ALG module triggers the sip alg (sip alg helps in translating the sip header and opening pinhole), and the resources are allocated.

    See the following debugs: 
    ## 2010-11-11 18:34:39 : >>>>>>>>> RECV PACKET begin 985 bytes >>>>>>>>>

## 2010-11-11 18:34:39 : INVITE sip:011919175971795@172.16.144.201 SIP/2.0
    ## 2010-11-11 18:34:39 : Route: <sip:172.16.144.201;lr>    
## 2010-11-11 18:34:39 : Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, SUBSCRIBE, OPTIONS, UPDATE, INFO
## 2010-11-11 18:34:39 : Supported: replaces,timer,100rel
## 2010-11-11 18:34:39 : User-Agent: OmniPCX Enterprise R9.0 h1.301.46
## 2010-11-11 18:34:39 : Session-Expires: 1800;refresher=uac
## 2010-11-11 18:34:39 : Min-SE: 900
## 2010-11-11 18:34:39 : P-Asserted-Identity: "Isbel Test" <sip:2199@172.16.8.3;user=phone>
## 2010-11-11 18:34:39 : Content-Type: application/sdp
## 2010-11-11 18:34:39 : To: sip:011919175971795@172.16.144.201
    ## 2010-11-11 18:34:39 : From: "Isbel Test" <sip:2199@172.16.8.3>;tag=512878eb4158a328093870e00d764700
    ## 2010-11-11 18:34:39 : Contact: <sip:172.16.8.3;transport=UDP>    
## 2010-11-11 18:34:39 : Call-ID: 65d4dd8f23212ebd6d8c72904f75e2e4@172.16.8.3
## 2010-11-11 18:34:39 : CSeq: 1129808556 INVITE
## 2010-11-11 18:34:39 : Via: SIP/2.0/UDP 172.16.8.3;branch=z9hG4bKf80547e9c96bd3187b0e1ec7d4143fd7
## 2010-11-11 18:34:39 : Max-Forwards: 70
## 2010-11-11 18:34:39 : Content-Length: 234
## 2010-11-11 18:34:39 : v=0
## 2010-11-11 18:34:39 : o=OXE 1289507934 1289507934 IN IP4 172.16.8.3
## 2010-11-11 18:34:39 : s=abs
## 2010-11-11 18:34:39 : c=IN IP4 172.16.8.21
    ## 2010-11-11 18:34:39 : t=0 0
    ## 2010-11-11 18:34:39 : m=audio 32514 RTP/AVP 18 97    ---Media port
## 2010-11-11 18:34:39 : a=sendrecv
## 2010-11-11 18:34:39 : a=rtpmap:18 G729/8000
## 2010-11-11 18:34:39 : a=fmtp:18 annexb=no
## 2010-11-11 18:34:39 : a=ptime:20
## 2010-11-11 18:34:39 : a=maxptime:40
## 2010-11-11 18:34:39 : a=rtpmap:97 telephone-event/8000
## 2010-11-11 18:34:39 : <<<<<<<<< RECV PACKET end <<<<<<<<<

## 2010-11-11 18:34:39 : sip_alg.... INCOMING call dlg2B4B30C
## 2010-11-11 18:34:39 : Transfer REQ URI
## 2010-11-11 18:34:39 : Transfer IP 172.16.144.201/5060/17
## 2010-11-11 18:34:39 : Transfer ROUTE URI [count 1]
## 2010-11-11 18:34:39 : Transfer Route addr
## 2010-11-11 18:34:39 : Transfer IP 172.16.144.201/5060/17
## 2010-11-11 18:34:39 : Transfer Session Expires
## 2010-11-11 18:34:39 : Transfer TO URI
## 2010-11-11 18:34:39 : Transfer IP 172.16.144.201/0/17
## 2010-11-11 18:34:39 : Transfer FROM URI
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.3/0/17
## 2010-11-11 18:34:39 : Transfer Contact count 1
## 2010-11-11 18:34:39 : Transfer Contact Expires value -1
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.3/5060/17
## 2010-11-11 18:34:39 : Transfer Via count 1
## 2010-11-11 18:34:39 : Transfer Via host
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.3/5060/17
## 2010-11-11 18:34:39 : Transfer SDP 'o' IP
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.3/5060/0
## 2010-11-11 18:34:39 : Transfer SDP session 'C'
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.21/0/0
## 2010-11-11 18:34:39 : Transfer SDP media:0
## 2010-11-11 18:34:39 : Transfer IP 172.16.8.21/32514/17
## 2010-11-11 18:34:39 : Transferred 1 media lines
## 2010-11-11 18:34:39 : Mark (REQ_URI) 172.16.144.201:5060 for xlation
## 2010-11-11 18:34:39 : Mark (FROM) 172.16.8.3:5060 for xlation
## 2010-11-11 18:34:39 : Mark (TO) 172.16.144.201:5060 for xlation
## 2010-11-11 18:34:39 : (Via) Xlate using peer_tsx
## 2010-11-11 18:34:39 : Mark (VIA addr) 172.16.8.3/5060 for xlation
## 2010-11-11 18:34:39 : Mark (VIA) 172.16.8.3/5060 for gate
## 2010-11-11 18:34:39 : Mark (ROUTE host) 172.16.144.201/5060 for xlation
## 2010-11-11 18:34:39 : Mark (CONTACT) 172.16.8.3:5060 for xlation
## 2010-11-11 18:34:39 : Mark (CONTACT) for pinhole-----
## 2010-11-11 18:34:39 : sip: [call] IP 172.16.8.21/5060 resolved to original ip 172.16.8.21/5060
## 2010-11-11 18:34:39 : sip: [call] Reached at ifp ethernet0/9.3 nexthop 172.16.8.21
## 2010-11-11 18:34:39 : sip: [exit] vsip_resolve_vsip:(638)
## 2010-11-11 18:34:39 : sip: [enter] vsip_resolve_vsip
## 2010-11-11 18:34:39 : sip: [call] IP 172.16.8.3/5060 resolved to original ip 172.16.8.3/5060
    ## 2010-11-11 18:34:39 : sip: [call] Reached at ifp ethernet0/9.3 nexthop 172.16.8.3
    ## 2010-11-11 18:34:39 : sip: [exit] vsip_resolve_vsip:(638)
    ## 2010-11-11 18:34:39 : sip: [enter] vsip_resolve_vsip
    ## 2010-11-11 18:34:39 : sip: [call] IP 172.16.144.201/5060 resolved to original ip 172.16.144.201/5060
    ## 2010-11-11 18:34:39 : sip: [call] Reached at ifp ethernet0/7 nexthop 172.18.1.113
    ## 2010-11-11 18:34:39 : sip: [exit] vsip_resolve_vsip:(638)
    ## 2010-11-11 18:34:39 : sip: [enter] vsip_nat_handler
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.21/32514 translated to 172.18.1.114/33010 (media ip and media port)
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.21/5060 translated to 172.18.1.114/13385
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.3/5060 translated to 172.18.1.114/21839
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.144.201/5060 translated to 172.16.144.201/5060
    ## 2010-11-11 18:34:39 : sip: [exit] vsip_nat_handler:(1287)
    ## 2010-11-11 18:34:39 : sip: [enter] vsip_rm_handler
    ## 2010-11-11 18:34:39 : sip: [rm] set pinhole rsc:3190,3196 for 172.16.8.21/32514 (172.16.8.21/32514), gates not opened
    ## 2010-11-11 18:34:39 : sip: [rm] set pinhole rsc:3199,0 for 172.16.8.3/5060 (172.16.8.3/5060), gates opened
    ## 2010-11-11 18:34:39 : sip: [rm] set pinhole rsc:3198,0 for 172.16.8.3/5060 (172.16.8.3/5060), gates not opened
    ## 2010-11-11 18:34:39 : sip: [exit] vsip_rm_handler:(2112)
    ## 2010-11-11 18:34:39 : ROUTE: need not xlate
    ## 2010-11-11 18:34:39 : Other: need not xlate
    ## 2010-11-11 18:34:39 : TO: need not xlate
    ## 2010-11-11 18:34:39 : FROM: create new hdr
    ## 2010-11-11 18:34:39 : CONTACT: create new hdr 0
    ## 2010-11-11 18:34:39 : VIA: create new hdr
    ## 2010-11-11 18:34:39 : sip_alg.... Dialog dlg2B4584C CALLING
    ## 2010-11-11 18:34:39 : sip_alg.... Dialog dlg2B4B30C sending provisional 100 (Trying)
    ## 2010-11-11 18:34:39 : sip_alg/rm sip registered rm group 638    
## 2010-11-11 18:34:39 : Transfer (CONTACT) to dlg2B4B30C: Local 172.16.8.3:5060
    ## 2010-11-11 18:34:39 : Transfer (CONTACT) to dlg2B4584C: Remote 172.18.1.114:21839    
## 2010-11-11 18:34:39 : Via host 172.16.8.3:5060 -> 172.18.1.114:21839

  3. From the above debugs, you can notice that the sip header is being translated. You can see that the To and Contact fields are being natted. Both the IP address and ports are translated. 
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.21/32514 translated to 172.18.1.114/33010 (media ip and media port)
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.21/5060 translated to 172.18.1.114/13385
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.8.3/5060 translated to 172.18.1.114/21839
    ## 2010-11-11 18:34:39 : sip: [nat] 172.16.144.201/5060 translated to 172.16.144.201/5060

  4. The translation firewall searches for the existing gates and, if not found, opens the gates. As per the above excerpt, logs group 638 is open. 
    ## 2010-11-11 18:34:39 : sip: [rm] set pinhole rsc:3190,3196 for 172.16.8.21/32514 (172.16.8.21/32514), gates not opened
    ## 2010-11-11 18:34:39 : sip: [rm] set pinhole rsc:3199,0 for 172.16.8.3/5060 (172.16.8.3/5060), gates opened
    ## 2010-11-11 18:34:39 : sip_alg/rm sip registered rm group 638


    Two sip dialogs are opened: 
    ## 2010-11-11 18:34:39 : Transfer (CONTACT) to dlg2B4B30C: Local 172.16.8.3:5060 > before translation
## 2010-11-11 18:34:39 : Transfer (CONTACT) to dlg2B4584C: Remote 172.18.1.114:21839 > after translation

    A Sip dialog is a peer-to-peer relationship between two user agents. It represents a context that facilitates the sequencing of messages between the user agents and proper routing of requests between both of them.

    Once the translation is done, the same packet is sent out. See the below message: 
    ## 2010-11-11 18:34:39 : > SEND PACKET begin 1014 bytes
## 2010-11-11 18:34:39 : INVITE sip:011919175971795@172.16.144.201 SIP/2.0
## 2010-11-11 18:34:39 : Route: <sip:172.16.144.201;lr>
## 2010-11-11 18:34:39 : Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, SUBSCRIBE, OPTIONS, UPDATE, INFO
## 2010-11-11 18:34:39 : Supported: replaces, timer, 100rel
## 2010-11-11 18:34:39 : User-Agent: OmniPCX Enterprise R9.0 h1.301.46
## 2010-11-11 18:34:39 : Session-Expires: 1800;refresher=uac
## 2010-11-11 18:34:39 : Min-SE: 900
## 2010-11-11 18:34:39 : P-Asserted-Identity: "Isbel Test" <sip:2199@172.16.8.3;user=phone>
## 2010-11-11 18:34:39 : To: sip:011919175971795@172.16.144.201
    ## 2010-11-11 18:34:39 : From: "Isbel Test" <sip:2199@172.18.1.114:21839>;tag=512878eb4158a328093870e00d764700
    ## 2010-11-11 18:34:39 : Contact: <sip:172.18.1.114:21839;transport=UDP> >     Ip and ports both have been translated.
## 2010-11-11 18:34:39 : Call-ID: 65d4dd8f23212ebd6d8c72904f75e2e4@172.16.8.3
## 2010-11-11 18:34:39 : CSeq: 1129808556 INVITE
## 2010-11-11 18:34:39 : Via: SIP/2.0/UDP 172.18.1.114:21839;branch=z9hG4bKf80547e9c96bd3187b0e1ec7d4143fd7
## 2010-11-11 18:34:39 : Max-Forwards: 70
## 2010-11-11 18:34:39 : Content-Type: application/sdp
## 2010-11-11 18:34:39 : Content-Length: 237
## 2010-11-11 18:34:39 : v=0
## 2010-11-11 18:34:39 : o=OXE 1289507934 1289507934 IN IP4 172.18.1.114
## 2010-11-11 18:34:39 : s=abs
## 2010-11-11 18:34:39 : c=IN IP4 172.18.1.114
## 2010-11-11 18:34:39 : t=0 0
## 2010-11-11 18:34:39 : m=audio 33010 RTP/AVP 18 97
## 2010-11-11 18:34:39 : a=sendrecv
## 2010-11-11 18:34:39 : a=rtpmap:18 G729/8000
## 2010-11-11 18:34:39 : a=fmtp:18 annexb=no
## 2010-11-11 18:34:39 : a=ptime:20
## 2010-11-11 18:34:39 : a=maxptime:40
## 2010-11-11 18:34:39 : a=rtpmap:97 telephone-event/8000
## 2010-11-11 18:34:39 : > SEND PACKET end

  5. The next time the packet is received, the resource module is hit for the SIP call. 
    ## 2010-11-11 18:34:39 : SIP processing success
    ## 2010-11-11 18:34:39 : sip_alg/rm callback code RM_HOLE_FIRST_HIT, group 638

    After the Initial Invite packet, the next expected sip packet is sip 100 Ringing. When the packet hits, the firewall searches for the resources allocated for the dialogues opened for that sip call.
    6.  ## 2010-11-11 18:34:39 : > RECV PACKET begin 346 bytes 
     ## 2010-11-11 18:34:39 : SIP/2.0 100 Trying
     ## 2010-11-11 18:34:39 : Via: SIP/2.0/UDP 172.18.1.114:21839;branch=z9hG4bKf80547e9c96bd3187b0e1ec7d4143fd7
     ## 2010-11-11 18:34:39 : From: "Isbel Test" <sip:2199@172.18.1.114:21839>;tag=512878eb4158a328093870e00d764700
     ## 2010-11-11 18:34:39 : To: sip:011919175971795@172.16.144.201;tag=gK0dcbd1ad
     ## 2010-11-11 18:34:39 : Call-ID: 65d4dd8f23212ebd6d8c72904f75e2e4@172.16.8.3
     ## 2010-11-11 18:34:39 : CSeq: 1129808556 INVITE
     ## 2010-11-11 18:34:39 : Content-Length: 0
     ## 2010-11-11 18:34:39 : > RECV PACKET end    

## 2010-11-11 18:34:39 : sip_alg.... Dialog dlg2B4584C received provisional 100 (Trying)
## 2010-11-11 18:34:39 : open gates for peer resources
## 2010-11-11 18:34:39 : update local tag of the callee dlg2B4B30C
## 2010-11-11 18:34:39 : update remote tag of the caller dlg2B4584C
## 2010-11-11 18:34:39 : Transfer Via count 1
## 2010-11-11 18:34:39 : Transfer Via host
## 2010-11-11 18:34:39 : Transfer IP 172.18.1.114/21839/17
## 2010-11-11 18:34:39 : Transfer FROM URI
## 2010-11-11 18:34:39 : Transfer IP 172.18.1.114/21839/17
## 2010-11-11 18:34:39 : Transfer TO URI
## 2010-11-11 18:34:39 : Transfer IP 172.16.144.201/0/17
    ## 2010-11-11 18:34:39 : (FROM) xlation found dlg 172.18.1.114:21839-> 172.16.8.3:5060
    ## 2010-11-11 18:34:39 : (TO) xlation found from dlg 172.16.144.201:5060-172.16.144.201:5060
    ## 2010-11-11 18:34:39 : (Via) Xlate using peer_tsx
    ## 2010-11-11 18:34:39 : (Via host) xlation found from tsx 172.18.1.114:21839 ->172.16.8.3:5060
    ## 2010-11-11 18:34:39 : open pinhole for peer contact rsc 3198
    ## 2010-11-11 18:34:39 : open pinhole for peer sdp rsc 3190:3196
    ## 2010-11-11 18:34:39 : sip: [enter] vsip_rm_handler
    ## 2010-11-11 18:34:39 : sip: [rm] existing pinhole rsc:3190,3196 gates opened
    ## 2010-11-11 18:34:39 : sip: [rm] existing pinhole rsc:3198,0 gates opened
    ## 2010-11-11 18:34:39 : sip_alg.... Dialog dlg2B4B30C sending provisional 100 (Trying)

  6. After the completion of all sip messages, the call will be established and you will see the following debug in the debug sip all output. 
    ## 2010-11-11 18:34:52 : > RECV PACKET begin 439 bytes
## 2010-11-11 18:34:52 : ACK sip:172.16.144.201:5060 SIP/2.0 > The final ack packet
## 2010-11-11 18:34:52 : Contact: sip:172.16.8.3
## 2010-11-11 18:34:52 : User-Agent: OmniPCX Enterprise R9.0 h1.301.46
## 2010-11-11 18:34:52 : To: sip:011919175971795@172.16.144.201;tag=gK0dcbd1ad
## 2010-11-11 18:34:52 : From: "Isbel Test" <sip:2199@172.16.8.3:5060>;tag=512878eb4158a328093870e00d764700
## 2010-11-11 18:34:52 : Call-ID: 65d4dd8f23212ebd6d8c72904f75e2e4@172.16.8.3
## 2010-11-11 18:34:52 : CSeq: 1129808556 ACK
## 2010-11-11 18:34:52 : Via: SIP/2.0/UDP 172.16.8.3;branch=z9hG4bK95edff5bf63381c0255afd930a873a33
## 2010-11-11 18:34:52 : Max-Forwards: 70
## 2010-11-11 18:34:52 : Content-Length: 0
## 2010-11-11 18:34:52 : < RECV PACKET end

## 2010-11-11 18:34:52 : sip_alg.... Dialog dlg2B4B30C ESTABLISHED on receiving ACK
    ## 2010-11-11 18:34:52 : sip_alg.... Dialog dlg2B4584C CONNECTED
    ## 2010-11-11 18:34:52 : sip_alg.... Dialog dlg2B4B30C CONNECTED


When troubleshooting, make sure to understand the setup correctly. Check the configuration and then start debugging.
Comment on this article > Affected Products Browse the Knowledge Base for more articles related to these product categories. Select a category to begin.

Getting Up and Running with Junos

Getting Up and Running with Junos Security Alerts and Vulnerabilities Product Alerts and Software Release Notices Problem Report (PR) Search Tool EOL Notices and Bulletins JTAC User Guide Customer Care User Guide Pathfinder SRX High Availability Configurator SRX VPN Configurator Training Courses and Videos End User Licence Agreement Global Search