5450ISC 内部呼叫跟踪简要流程

5450ISC 内部呼叫跟踪简要流程
一、Trace 方法：
1.用lss登录：
2.logCtrl
3.依次选择
4.tail -F master.log
<shlab-s00c01h0:lss>/export/home/lss/logs:
# who am i
lss pts/3 Jun 30 09:45 (10.0.1.149)
<shlab-s00c01h0:lss>/export/home/lss/logs:
# logCtrl
Log control main menu:
1: Host sub menu
2: Restore all clients to default setting
q: Quit
Please enter your selection(1-2), Return(r) or Quit(q):
1
Index IP Address Host Name Service List
=============================================================
1 169.254.64.16 shlab-s00c01h0 cnfg/mi/sns
2 169.254.64.32 shlab-s00c02h0 cnfg/mi/sns
3 169.254.64.48 shlab-s00c03h0 h248/ims
4 169.254.64.64 shlab-s00c04h0 h248/ims
Please enter your selection(1-4), Return(r) or Quit(q):
3
Log Client Submenu for shlab-s00c03h0 [169.254.64.48]
Index Client Name Log Level Debug Level ---------------------------------------------------------------------
1 anonymous
2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
2 ipm-169.254.64.48 2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
3 lxprofile-169.254.64.48 2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
4 IPmon-169.254.64.48 2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
5 aim-169.254.64.48 2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
6 LCPlogLocal-169.254.64.48 2 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
7 h248ds-169.254.139.0 2 0
8 ngss-169.254.154.0 4 0
Message Class=0xffffffff ffffffff ffffffff ffffffff
Please enter your selection(1-8), Return(r) or Quit(q):
q
Exiting logCtrl.
<shlab-s00c01h0:lss>/export/home/lss/logs:
# tail -F master.log
二、SIP to SIP call 消息流程
以下是一个实验室软phone终端用SIP互拨正常接通的流程，实际现场VoLTE流程会更复杂点。

主叫：862133000001
被叫：862133000002
主叫/被叫终端IP：10.0.0.71
IMS服务IP：10.0.0.204
1，主叫终端发起呼叫，发INVITE（带SDP）给P-CSCF
SS:SIPtrans Message Log (0x2fc01e1c:0x2fc01f44):
Fri Jul 1 11:44:54 2016 (1467373494.717099)
RECEIVED from [10.0.0.71]:6060 over UDP on local socket=76 [10.0.0.204]:5060
[INVITE tel:+862133000002 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.71:6060;rport;branch=z9hG4bK5775e350-00222d
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57764ee7
Contact: <sip:+862133000001@10.0.0.71:6060;transport=udp>
Call-ID: ZdmAg16229-ID00000026-H11M028S16@10.0.0.71
CSeq: 71 INVITE
P-Preferred-Identity: <sip:+862133000001@;user=phone>
Route: <sip::5060;lr;bidx=0>
Max-Forwards: 70
User-Agent: Chinamobile-Ucommunicator/vb3.2.1.87
Supported: 100rel,timer,replaces,P-Early-Media
P-Early-Media: supported
Min-SE: 90
Session-Expires: 1000
Allow: INVITE,MESSAGE,INFO,PRACK,PUBLISH,SUBSCRIBE,OPTIONS,UPDATE,BYE,CANCEL,NOTIFY,ACK,REFER Content-Type: application/sdp
Content-Length: 196
（下面几行为SDP）
v=0
o=+862133000001 2208988851 0 IN IP4 10.0.0.71
s=TOMORROW
c=IN IP4 10.0.0.71
t=0 0
a=rtpmap:121 AMR/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
]
IMS服务收到INVITE后向用户A 发送100（trying）确认信号，表示正在对收到的请求进行处理。

（SIP协议中，响应消息是一个3位数+词语）
+++ 2016/07/01 11:44:54.717 IMS MEDIUM ACTIVE ngss:15143 E:2628295 S:2326274 (SIPNet.cpp 4371 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SS:SIPtrans Message Log (0x34b0abfc:(nil)):
Fri Jul 1 11:44:54 2016 (1467373494.717267)
SENDING from socket=76 [10.0.0.204]:5060 over UDP to [10.0.0.71]:6060
[SIP/2.0 100 Trying
Call-ID: ZdmAg16229-ID00000026-H11M028S16@10.0.0.71
Via: SIP/2.0/UDP 10.0.0.71:6060;received=10.0.0.71;branch=z9hG4bK5775e350-00222d;rport=6060
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57764ee7
CSeq: 71 INVITE
Date: Fri, 01 Jul 2016 11:44:54 GMT
Server: Alcatel-Lucent-HPSS/3.0.3
Content-Length: 0
]
+++ 2016/07/01 11:44:54.717 IMS MEDIUM ACTIVE ngss:15143 E:2628296 S:2326275 (Siptrans_invoke.cpp 111 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SS:SIPtrans Message Log (0x34b11dbc:(nil)):
Fri Jul 1 11:44:54 2016 (1467373494.717297)
SENDING from network to (1)
[INVITE tel:+862133000002 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_001_44614-884291676
Via: SIP/2.0/UDP 10.0.0.71:6060;received=10.0.0.71;branch=z9hG4bK5775e350-00222d;rport=6060
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57764ee7
Contact: <sip:+862133000001@10.0.0.71:6060;transport=udp>
Call-ID: ZdmAg16229-ID00000026-H11M028S16@10.0.0.71
CSeq: 71 INVITE
P-Preferred-Identity: <sip:+862133000001@;user=phone>
Route: <sip::5060;lr;bidx=0>
Max-Forwards: 69
User-Agent: Chinamobile-Ucommunicator/vb3.2.1.87
Supported: 100rel,timer,replaces,P-Early-Media
P-Early-Media: supported
Min-SE: 90
Session-Expires: 1000
Content-Type: application/sdp
Content-Length: 196
v=0
o=+862133000001 2208988851 0 IN IP4 10.0.0.71
s=TOMORROW
c=IN IP4 10.0.0.71
t=0 0
m=audio 39720 RTP/AVP 0 8 121 101
a=rtpmap:121 AMR/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
]
2，P-CSCF发INVITE给主叫S-CSCF
SS:SIPtrans Message Log (0x34b42e5c:(nil)):
Fri Jul 1 11:44:54 2016 (1467373494.718642)
SENDING from (1) directly to (3) [INVITE tel:+862133000002 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_003_44615-884080668
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_001_1467373494-718234-49-LucentPCSF
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57710028-577657b62acf1b21-mw-po-lucentPCSF-000046 Contact: <sip:+862133000001@:5060;ue-addr=10.0.0.71>
Call-ID: LU-1467373494718212-23@
CSeq: 1 INVITE
Route: <sip::5062;lr;ottag=ue_orig;bidx=1>
Max-Forwards: 68
User-Agent: Chinamobile-Ucommunicator/vb3.2.1.87
Supported: replaces,P-Early-Media,100rel
P-Early-Media: supported
Allow: INVITE,MESSAGE,INFO,PRACK,PUBLISH,SUBSCRIBE,OPTIONS,UPDATE,BYE,CANCEL,NOTIFY,ACK,REFER Content-Type: application/sdp
Content-Length: 212
P-Asserted-Identity: <sip:+862133000001@;user=phone>
P-Charging-Vector: icid-value="PCSF:10.0.0.204-5060-577657b6-000001c8"
v=0
o=LucentPCSF 666479617 666479617 IN IP4
s=-
c=IN IP4 10.0.0.71
t=0 0
m=audio 39720 RTP/AVP 0 8 121 101
a=rtpmap:121 AMR/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
3，主叫S-CSCF发INVITE消息给主叫TAS进行被叫号码补全（实验室无TAS，此步骤略）
紧接着主叫S-CSCF发起ENUM query，DNS解析
IMS:Prep for ENUM Query: comp=3,port=3,role=0,icid=3,uniqueness=2616
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628468 S:2326444 (aDNSnonblocking.cpp 1136 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:The request was appended to the pending response list: id=56676
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628469 S:2326445 (aDNSnonblocking.cpp 919 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:Sending a new query request to 127.0.0.1. qid=886958236; id=56676; request=4; cache=0; data=2.0.0.0.0.0.3.3.1.2.6.8.e164.arpa; data_len=33.
（ENUM是颠倒的）
+++ 2016/07/01 11:44:54.719 NGSS LOW ACTIVE ngss:15143 E:2628470 S:2326446 (TRANS 5 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Calling transSendBytes for datagram
+++ 2016/07/01 11:44:54.719 NGSS LOW ACTIVE ngss:15143 E:2628471 S:2326447 (TRANS 5 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Calling send(sock = 28, buf = 0x34b0835c, length = 62,flags=0)
+++ 2016/07/01 11:44:54.719 IMS MEDIUM ACTIVE ngss:15143 E:2628473 S:2326448 (EnumProcessor.cpp 274 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF: ENUM Query Sent (TEL-URI) with hex support = 0 - +862133000002.
+++ 2016/07/01 11:44:54.719 IMS LOW ACTIVE ngss:15143 E:2628474 S:2326449 (IMSTimer.cpp 115 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS_INFRA:IMSTimer start() timer=0x34d515dc, key=430, time=2000
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628475 S:2326450 (aDNSnonblocking.cpp 1529 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:Received a query response: id=56676 request=4 rcode=0
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628476 S:2326451 (aDNSnonblocking.cpp 2506 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:Remove a request from the pending response list: id=56676
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628477 S:2326452 (aDNSutil.cpp 1037 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:aDNSnaptr: aDNSnaptr_service() returned rrcount=0; service_type=1
+++ 2016/07/01 11:44:54.719 TRACE LOW ACTIVE ngss:15143 E:2628478 S:2326453 (aDNSutil.cpp 1088 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:NAPTR RR Replacement Harvested Length (1), Field ()
（DNS解析）
+++ 2016/07/01 11:44:54.720 TRACE LOW ACTIVE ngss:15143 E:2628479 S:2326454 (aDNSutil.cpp 571 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:Regular Expression done: source=[+862133000002] rexp=[!86213([0-9]{7})$] result=[sip:+862133000002@;user=phone]
+++ 2016/07/01 11:44:54.720 TRACE LOW ACTIVE ngss:15143 E:2628480 S:2326455 (aDNSnonblocking.cpp 1885 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ADNS:Calling response handler and releasing memory for qid=886958236
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628481 S:2326456 (CPscscf_nr_waitdns.cpp 572 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:SCSCF SM_TRACE icid = 3, state = SCSCF_NR_WAITDNS, event = STI_DQ_DNS_EVENT, ns_rcode = 0, request_status = 4
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628482 S:2326457 (IMSTimer.cpp 72 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS_INFRA:IMSTimer destroy has active timer=0x34d515dc running, stop
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628483 S:2326458 (CPscscf_nr_waitdns.cpp 680 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:CPscscf_nr_waitdns(): URI Alias String(sip:+862133000002@;user=phone); service_type(1)
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628485 S:2326459 (CPcscf_acr_infra_util.cpp 3918 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ACR:CPutil_getCICFromURI(): No cic parameter in URI, cicDstrPtr:(nil), digitLen:13
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628486 S:2326460 (CPcscf_acr_infra_util.cpp 4195 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ACR:CPutil_getRNFromURI(): No RN parameter in URI, rnDstrPtr:(nil), digitLen:13
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628487 S:2326461 (CPscscf_nr_routing.cpp 970 A-0:3:0
S-CSCF:CPscscf_pq_route(): SIP URI Received.
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628488 S:2326462 (CPdomn_util.cpp 234 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:CPutil_domain_type returned IMSDOMN_LOCAL
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628489 S:2326463 (CPscscf_crf_util.cpp 1024 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:After enum CRF process is not configured, will be skipped
4，主叫S-CSCF选路到被叫I-CSCF
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628490 S:2326464 (CPscscf_nr_routing.cpp 1263 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:CPscscf_pq_route(): Routing to ICSCF
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628491 S:2326465 (CPscscf_tcm_util.cpp 68 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:CPscscf_send2BBAM entered
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628492 S:2326466 (CPscscf_tcm_util.cpp 84 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:transcoding is not enabled
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628493 S:2326467 (CPcscf_ioi_util.cpp 213 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:CPcscf_add_ioi_param() - Added ORIG IOI "shlab", sipia_ret=1
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628494 S:2326468 (CPscscf_pChargeVector_hdr_util.cpp 180 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
S-CSCF:CPscscf_rmv_chrg_param_from_PCV(): No charging info parameter present in PCV
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628495 S:2326469 (SSmain.cpp 2417 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SIPtrans Log:
Fri Jul 1 11:44:54 2016 (1467373494.720390)
SSsend_msg_to_SS(): application SIPia - available_mem=3820, blk_size=9552
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628496 S:2326470 (SSgeo_redundancy.cpp 187 A-0:3:0
IMS:SSgetPNAPTRrecordList: Msg's Host-Name is Local; goto siptrans to do DNS For PNAPTRost-Name must be Remote
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628497 S:2326471 (SScfed_bypass.cpp 89 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:SScfed_bypass(): CFED for the Provisioned sipia port 3 is DISABLED; no treatment applied.
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628498 S:2326472 (Siptrans_message.cpp 421 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SIPtrans Log:
Fri Jul 1 11:44:54 2016 (1467373494.720430)
RECEIVED from TU a INVITE request (msgp=0x34b49e5c)
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628500 S:2326473 (SSlss_sip_ia_port.cpp 2566 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:SSgul_pre_DNS_resolve: LOCAL, port_idx 2, state 1, gul icsf-stdn
（DNS解析结果：local，icsf-stdn）
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628501 S:2326474 (Siptrans_invoke.cpp 111 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
5，主叫S-CSCF发INVITE（带补全号码）到被叫I-CSCF
SS:SIPtrans Message Log (0x34b49e5c:(nil)):
Fri Jul 1 11:44:54 2016 (1467373494.720497)
SENDING from (3) directly to (2)
[INVITE sip:+862133000002@;user=phone;x-enumdi SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_002_44616-884153404
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_003_44615-884080668;dp;lsstag=so-47-47.2616
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_001_1467373494-718234-49-LucentPCSF
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57710028-577657b62acf1b21-mw-po-lucentPCSF-000046 Contact: <sip:+862133000001@:5060>
Call-ID: LU-1467373494718212-23@
CSeq: 1 INVITE
Route: <sip:;lr>
Max-Forwards: 67
User-Agent: Chinamobile-Ucommunicator/vb3.2.1.87
Supported: replaces,P-Early-Media,100rel
P-Early-Media: supported
Allow: INVITE,MESSAGE,INFO,PRACK,PUBLISH,SUBSCRIBE,OPTIONS,UPDATE,BYE,CANCEL,NOTIFY,ACK,REFER
Content-Type: application/sdp
Content-Length: 212
P-Asserted-Identity: <sip:+862133000001@;user=phone>
P-Asserted-Identity: <tel:+862133000001>
Record-Route: <sip::5062;lr;sdp=ck;lsstag=so-47-47.2616>
v=0
o=LucentPCSF 666479617 666479617 IN IP4
s=-
c=IN IP4 10.0.0.71
t=0 0
m=audio 39720 RTP/AVP 0 8 121 101
a=rtpmap:121 AMR/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
]
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628502 S:2326475 (SSmain.cpp 1985 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SIPtrans Log:
Fri Jul 1 11:44:54 2016 (1467373494.720549)
Siptrans_sip_message_to_TU_2():
before clone SIPia - available_mem=3248, blk_size=9552
after clone SIPia - available_mem=4272, blk_size=10576
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628503 S:2326476 (CPcscf_new_util.cpp 3090 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:CPutil_remove_extra_pani(): There is no PANI in SIP message, so just return
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628504 S:2326477 (CPcscf_acr_infra.cpp 9432 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ACR:CPcscf_initACRChargingInfo(): ACR version:3,isPopulateSIPMilliseconds:0,isPopulateRingingTimeStamp:0
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628505 S:2326478 (CALLTRACE_manager.cpp 2656 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:SipMonSetCriteria Enter
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628506 S:2326479 (CALLTRACE_manager.cpp 2666 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:The message has been traced in upstream NE, use the old trace ID index 0
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628507 S:2326480 (SSmain.cpp 2417 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SIPtrans Log:
Fri Jul 1 11:44:54 2016 (1467373494.720609)
SSsend_msg_to_SS(): application SIPia - available_mem=2216, blk_size=8716
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628508 S:2326481 (Siptrans_message.cpp 421 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
SIPtrans Log:
Fri Jul 1 11:44:54 2016 (1467373494.720627)
RECEIVED from TU a 100-INVITE response (msgp=0x34d566fc)
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628509 S:2326482 (CPicscf_start.cpp 195 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:ICSCF SM_TRACE icid = 4, state = STI_ICSCF_START, event = STI_RECVMSG_EVENT, SIP request = INVITE
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628510 S:2326483 (CPrtcf_start.cpp 119 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:CPicscf_non_reg_start(): addr_resolution_method = 0, prov_port_idx = 2
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628512 S:2326484 (CPcscf_acr_infra.cpp 1093 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
ACR:CPcscf_new_acr() entered: icr=0x34b3d5fc, APPL '1', ROLE '1', pDialog '0', msgType '1'
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628513 S:2326485 (CPcscf_priority_util.cpp 1427 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:initial INVITE received, 0 treatment is set for application 1, icr 0x34b3d5fc
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628514 S:2326486 (CPrtcf_start.cpp 512 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:Cx only does not check allowserving host.
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628515 S:2326487 (CPrtcf_start.cpp 1099 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:Start Term, addr_resolution_method = 0
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628516 S:2326488 (CPrtcf_start.cpp 1108 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:ACR buffer already exist, change the ACR role to TERM
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628517 S:2326489 (CPrtcf_start.cpp 1127 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:Apply XENUMDI treatment (Bypass ENUM).
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628518 S:2326490 (CPrtcf_routing.cpp 1349 A-0:3:0
I-CSCF:CPrtcf_send_lir(): Check to see if SIP uri should be converted to TEL uri.
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628519 S:2326491 (CPrtcf_routing.cpp 1372 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
I-CSCF:public_id_ptr = tel:+862133000002
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628520 S:2326492 (STIpack_cxid.cpp 79 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS_INFRA:Prep for HSS query: comp=3,port=2,role=1,icid=4
+++ 2016/07/01 11:44:54.720 IMS LOW ACTIVE ngss:15143 E:2628521 S:2326493 (IMScx.cpp 280 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:cx_compose_SessionId checksum (1570439480), SessionId (;132122369;1570439480)
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628522 S:2326494 (IMScx.cpp 2967 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:Destination-Host is :localhost:
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628523 S:2326495 (IMScx.cpp 2987 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:Destination-Realm is :localhost:
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628524 S:2326496 (IMScx.cpp 5365 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:CXsend_lir(): the unproper UserAuthorizationType.
6，I-CSCF发LIR（LocationInfoRequest，DIAMETER协议）给HSS查询被叫用户所属的S-CSCF
HSS 处理逻辑：
1、当用户的状态为registered或者unregistered, HSS返回S-CSCF的名字
2、当用户的状态为not registered, 而且用户签约了未注册状态业务, HSS返回S-CSCF名字或者能力集
3、其他情况，HSS返回响应的错误信息
+++ 2016/07/01 11:44:54.720 IMS MEDIUM ACTIVE ngss:15143 E:2628525 S:2326497 (IMScx.cpp 5400 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:
=============== Dump from cxSendLIR() - before encoding:
APPLICATION DATA:
version (1B) = 0x01 - 1
requestFlag (1b) = 1
proxyableFlag (1b) = 1
errorFlag (1b) = 0
retransFlag (1b) = 0
cmdCode (3B) = 0x00012e - 302
appIdType (4B) = 0x00000000 - 0
hopByHopId (4B) = 0x5b2112e6 - 1528894182
endToEndId (4B) = 0x7b6796e1 - 2070386401
Command LocationInfoRequest:
AVP SessionId 1/1 = ;132122369;1570439480
AVP VendorSpecificApplicationId 1/1
AVP VendorId 1/4 = 0x000028af - 10415
AVP AuthApplicationId 1/1 = 0x01000000 - 16777216
AVP AuthSessionState 1/1 = 0x00000001 - 1 - NoStateMaintained
AVP OriginHost 1/1 =
AVP OriginRealm 1/1 =
AVP DestinationHost 1/1 = localhost
AVP DestinationRealm 1/1 = localhost
AVP SupportedFeatures 1/26
AVP VendorId 1/1 = 0x000028af - 10415
AVP FeatureListID 1/1 = 0x00000001 - 1
AVP FeatureList 1/1 = 0x00000004 - 4
AVP PublicIdentity 1/1 = tel:+862133000002
+++ 2016/07/01 11:44:54.720 DIAMETER LOW ACTIVE ngss:15143 E:2628526 S:2326498 (DiamTcp.cpp 375 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Application: Cx, Application Instance ID: 0
DiamTcp::send: try to send 328 bytes raw message[0xb7e45f8] on localIndex[0], remoteIndex[0]
+++ 2016/07/01 11:44:54.720 DIAMETER LOW ACTIVE ngss:15143 E:2628527 S:2326499 (DiamLayer3Base.cpp 1505 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Application: Cx, Application Instance ID: 0
TCP send, local 0 10.0.0.204:33936, remote 0 10.0.0.203:3868, TCP layer: connected, Diameter layer: connected LocationInfoRequestdata (328 bytes), hex dump:
01000148 c000012e 01000000 5b2112e6 7b6796e1 00000107 40000043 69637366
2d737464 6e2e696d 732d3030 3030302e 73686c61 622e7368 2e637463 696d732e
636e3b31 33323132 32333639 3b313537 30343339 34383000 00000104 40000020
0000010a 4000000c 000028af 00000102 4000000c 01000000 00000115 4000000c
00000001 00000108 4000002e 69637366 2d737464 6e2e696d 732d3030 3030302e
73686c61 622e7368 2e637463 696d732e 636e0000 00000128 40000014 73682e63
7463696d 732e636e 00000125 40000011 6c6f6361 6c686f73 74000000 0000011b
40000011 6c6f6361 6c686f73 74000000 00000274 80000038 000028af 0000010a
30303030 32000000
+++ 2016/07/01 11:44:54.720 NGSS LOW ACTIVE ngss:15143 E:2628528 S:2326500 (TRANS 5 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Calling send(sock = 91, buf = 0xb7e45f8, length = 328,flags=0)
+++ 2016/07/01 11:44:54.721 NGSS LOW ACTIVE ngss:15143 E:2628532 S:2326501 (TRANS 5 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
calling TransNotifyPacketArrived, length=248
+++ 2016/07/01 11:44:54.721 DIAMETER LOW ACTIVE ngss:15143 E:2628533 S:2326502 (DiamLayer3Base.cpp 2425 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Application: Cx, Application Instance ID: 0
DiamLayer3Base::onRecved: received 248 bytes raw message[0x34d65c40] on localIndex[0], remoteIndex[0]
7，HSS回LIA（LocationInfoAnswerdata，带着能力集Capability=10）给I-CSCF
I-CSCF收到LIA后从局数据中查找能力集10找到对应的S-CSCF
+++ 2016/07/01 11:44:54.721 DIAMETER LOW ACTIVE ngss:15143 E:2628534 S:2326503 (DiamLayer3Base.cpp 1505 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
Application: Cx, Application Instance ID: 0
Diam TCP receive, local 0 10.0.0.204:33936, remote 0 10.0.0.203:3868, TCP layer: connected, Diameter layer: connected LocationInfoAnswerdata (252 bytes), hex dump:
010000fc 4000012e 01000000 5b2112e6 7b6796e1 00000107 40000043 69637366
2d737464 6e2e696d 732d3030 3030302e 73686c61 622e7368 2e637463 696d732e
636e3b31 33323132 32333639 3b313537 30343339 34383000 00000104 40000020
0000010a 4000000c 000028af 00000102 4000000c 01000000 00000108 4000001c
4c49415f 4f726967 696e6174 696f6e5f 486f7374 00000128 4000001d 4c49415f
4f726967 696e6174 696f6e5f 5265616c 6d000000 0000025b c000001c 000028af
0000025c c0000010 000028af 0000000a 00000129 40000020 0000010a 4000000c
00004c1f 0000012a 4000000c 000007d3 00000115 4000000c 00000001
+++ 2016/07/01 11:44:54.721 DIAMETER LOW ACTIVE ngss:15143 E:2628537 S:2326504 (DiamCmdBase.cpp 166 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
cmdCode 0x12e
+++ 2016/07/01 11:44:54.721 IMS MEDIUM ACTIVE ngss:15143 E:2628539 S:2326505 (IMSdiamCx.cpp 4984 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:procMsgFromHss(): Received cmd code=302
+++ 2016/07/01 11:44:54.721 DIAMETER MEDIUM ACTIVE ngss:15143 E:2628540 S:2326506 (IMSdiamCx.cpp 1179 A-0:3:0
Application: Cx,
=============== Dump from cxPassCRespToLsm():
APPLICATION DATA:
Message:
version (1B) = 0x01 - 1
requestFlag (1b) = 0
proxyableFlag (1b) = 1
errorFlag (1b) = 0
retransFlag (1b) = 0
cmdCode (3B) = 0x00012e - 302
appIdType (4B) = 0x00000000 - 0
hopByHopId (4B) = 0x5b2112e6 - 1528894182
endToEndId (4B) = 0x7b6796e1 - 2070386401
Command LocationInfoAnswer:
AVP SessionId 1/1 = ;132122369;1570439480
AVP VendorSpecificApplicationId 1/1
AVP VendorId 1/4 = 0x000028af - 10415
AVP AuthApplicationId 1/1 = 0x01000000 - 16777216
AVP AuthSessionState 1/1 = 0x00000001 - 1 - NoStateMaintained
AVP OriginHost 1/1 = LIA_Origination_Host
AVP OriginRealm 1/1 = LIA_Origination_Realm
AVP ExperimentalResult 1/1
AVP VendorId 1/1 = 0x00004c1f - 19487
AVP ExperimentalResultCode 1/1 = 0x000007d3 - 2003
AVP ServerCapabilities 1/1
AVP MandatoryCapability 1/10 = 0x0000000a - 10
+++ 2016/07/01 11:44:54.721 IMS MEDIUM ACTIVE ngss:15143 E:2628541 S:2326507 (IMSdiamCx.cpp 3108 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:retrieveLIAdata() - SessionID: ;132122369;1570439480
+++ 2016/07/01 11:44:54.721 IMS LOW ACTIVE ngss:15143 E:2628542 S:2326508 (IMSdiamCx.cpp 3365 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:retrieveLIAdata(): Wildcarded-PSI AVP is NOT used! proceeding...
+++ 2016/07/01 11:44:54.721 IMS LOW ACTIVE ngss:15143 E:2628543 S:2326509 (IMScx.cpp 1289 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS:CXhandle_resp_msg(): pending_ptr->private_id is not valid for hss_msg_type :8:
+++ 2016/07/01 11:44:54.721 IMS LOW ACTIVE ngss:15143 E:2628544 S:2326510 (STIcx_rsp.cpp 84 A-0:3:0
IMS_INFRA:Received Cx response: comp=3,port=2,,icid=4
+++ 2016/07/01 11:44:54.721 IMS LOW ACTIVE ngss:15143 E:2628545 S:2326511 (STIproc_cxrsp.cpp 43 A-0:3:0 29.19.01.10:1418128941 lssbld 169.254.154.0)
IMS_INFRA:comp=3,port=2,icid=4,int_retcode=0,ext_retcode=2003
8，被叫I-CSCF发INVITE给被叫S-CSCF
SS:SIPtrans Message Log (0x34ddeb1c:(nil)):
Fri Jul 1 11:44:54 2016 (1467373494.721718)
SENDING from (2) directly to (3)
[INVITE tel:+862133000002 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_003_44617-884422620
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_002_44616-884153404;lsstag=it-4.2617
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_003_44615-884080668;dp;lsstag=so-47-47.2616
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK_001_1467373494-718234-49-LucentPCSF
To: <tel:+862133000002>
From: <sip:+862133000001@>;tag=57710028-577657b62acf1b21-mw-po-lucentPCSF-000046 Contact: <sip:+862133000001@:5060>
Call-ID: LU-1467373494718212-23@
CSeq: 1 INVITE
Route: <sip:;lr>
Max-Forwards: 66
User-Agent: Chinamobile-Ucommunicator/vb3.2.1.87
Supported: replaces,P-Early-Media,100rel
P-Early-Media: supported
Allow: INVITE,MESSAGE,INFO,PRACK,PUBLISH,SUBSCRIBE,OPTIONS,UPDATE,BYE,CANCEL,NOTIFY,ACK,REFER
Content-Type: application/sdp
Content-Length: 212
P-Asserted-Identity: <sip:+862133000001@;user=phone>
P-Asserted-Identity: <tel:+862133000001>
P-Charging-Vector: icid-value="PCSF:10.0.0.204-5060-577657b6-000001c8";orig-ioi="shlab"
Record-Route: <sip::5062;lr;sdp=ck;lsstag=so-47-47.2616>
v=0
o=LucentPCSF 666479617 666479617 IN IP4
s=-
c=IN IP4 10.0.0.71
t=0 0
m=audio 39720 RTP/AVP 0 8 121 101
a=rtpmap:121 AMR/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
]。