[Spce-user] Cable modem reinvite NAT issue.
=?utf-8?B?S2VsZW1lbiDBcnDhZA==?=
arpad.kelemen at g-online.hu
Mon Nov 7 10:36:13 EST 2011
Dear Jonathan,
I already cross the mentioned posting but unfortunately my issue is just
one way. In case if the call is between subscribers or the call come from
PSTN all work perfectly.
The following log is get from the modem (debug mode). You will see the
INVITE at 13:23:08.610 11/04/2011 "Failed to update call trace info" and
the BEY at 13:23:19.200 11/04/2011
:23:08.570 11/04/2011 (CALC) DBG: gwRtpStreamModify(): Modify SF(switch to
BE if UGS fails)...
13:23:08.580 11/04/2011 (SNMP) DBG: Taking ACTION for Event <258i>
13:23:08.580 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:08.580 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:08.580 11/04/2011 (SNMP) DBG: Taking ACTION for Event <259i>
13:23:08.580 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:08.580 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_MODIFY_PROCESS]
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) DBG: ENDPT 0: forcing T.38 data
mode 3 into VBD
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) INFO: EnableRelay: VBD mode for
endpt 0
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) INFO: DTMF Relay 0, Fax 1
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) INFO: Set codec: codec=0x2,
pc=0x1, s=0, p=20
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) DBG: ENDPT 0: cnx 0 - set RTP
registers and payload types
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) DBG: Setting RTP service
registers for line 0
13:23:08.580 11/04/2011 [VRGCMGR] (EPT) DBG: SetRtpServiceRegisters:
setting loopback parameters: mode:0, lbMirror:0, bStart:0, payload:0
13:23:08.580 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_ACTIVE], ri=0
13:23:08.580 11/04/2011 [VRGCMGR] (CMGR) DBG: cmStreamRxInfo: cid 5, ep
0, rtpcx 0: CODEC_PCMA, 20ms, VAD
13:23:08.580 11/04/2011 [VRGCMGR] (CMGR) DBG: Modifying stream 0
13:23:08.590 11/04/2011 [VRGCMGR] (CMGR) DBG: cmStreamRxInfo ingressCodec
codec list:
13:23:08.590 11/04/2011 [VRGCMGR] (CMGR) DBG: (1): 8=2
13:23:08.590 11/04/2011 [VRGCMGR] (CMGR) DBG: cmStreamRxInfo egressCodec
codec list:
13:23:08.590 11/04/2011 [VRGCMGR] (CMGR) DBG: (1): 8=2
13:23:08.590 11/04/2011 (CALC) DBG: secGetSignatureSize: (0)
13:23:08.590 11/04/2011 (CALC) DBG: gwRtpStreamModify(): Modify SF(switch
to BE if UGS fails)...
13:23:08.590 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:08.600 11/04/2011 [SipAppCoreTrans] (CMGR) INFO: cmEventCallback:
evt 5, cid 5, sta -1, res 27, pkt 0, str
13:23:08.600 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_MODIFY_PROCESS]
13:23:08.600 11/04/2011 [VRGCMGR] (EPT) DBG: ENDPT 0: forcing T.38 data
mode 3 into VBD
13:23:08.600 11/04/2011 [VRGCMGR] (EPT) INFO: Set codec: codec=0x2,
pc=0x1, s=0, p=20
13:23:08.600 11/04/2011 [VRGCMGR] (EPT) DBG: ENDPT 0: cnx 0 - set RTP
registers and payload types
13:23:08.600 11/04/2011 [VRGCMGR] (EPT) DBG: Setting RTP service
registers for line 0
13:23:08.600 11/04/2011 [VRGCMGR] (EPT) DBG: SetRtpServiceRegisters:
setting loopback parameters: mode:0, lbMirror:0, bStart:0, payload:0
13:23:08.600 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_ACTIVE], ri=0
13:23:08.600 11/04/2011 [VRGCMGR] (CMGR) DBG: evt: 0x3005, op1: 5, op2:
27, class: 0x3000
13:23:08.600 11/04/2011 [VRGCMGR] (CMGR) INFO: cmProcessCallEvent: cid
0x5, event 5 CCEVT_STATUS, reason 27 CCRSN_ACK, packet 0
13:23:08.600 11/04/2011 (SNMP) DBG: Taking ACTION for Event <258i>
13:23:08.600 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:08.600 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
[SIG-LOG] (SIP) DBG: SIP <<<<< Recv 1107 bytes from SIP_SERVER:5060 to
10.41.3.87:5060 <<<<<
INVITE sip:3628700025 at 10.41.3.87:5060;transport=udp SIP/2.0
Record-Route:
<sip:SIP_SERVER;r2=on;lr=on;ftag=7D2ED34A-4EB3E6A4000979A1-F5A0D700>
Record-Route:
<sip:127.0.0.1;r2=on;lr=on;ftag=7D2ED34A-4EB3E6A4000979A1-F5A0D700>
Max-Forwards: 9
Record-Route:
<sip:127.0.0.1:5062;lr=on;ftag=7D2ED34A-4EB3E6A4000979A1-F5A0D700>
Via: SIP/2.0/UDP SIP_SERVER;branch=z9hG4bK6e32.a0093532.0
Via: SIP/2.0/UDP
127.0.0.1:5062;rport=5062;branch=z9hG4bK6e32.f1e42851d87fa0506ee14c363d48e6cf.0
Via: SIP/2.0/UDP 127.0.0.1:5080;branch=z9hG4bKrPzRzakb;rport=5080
From: <sip:0612314441 at SIP_DOMAIN:5060>;tag=7D2ED34A-4EB3E6A4000979A1-F5A0D700
To: "3628700025" <sip:3628700025 at SIP_DOMAIN>;tag=63ba74dc0e
CSeq: 11 INVITE
Call-ID: c911c754909916ed
Contact: <sip:b2b-3612314441 at 127.0.0.1:5080>
Supported: timer
Session-Expires: 300
Min-SE: 90
Content-Type: application/sdp
Content-Length: 195
v=0
o=- 797628450 450196899 IN IP4 SIP_SERVER
s=-
c=IN IP4 SIP_SERVER
t=0 0
m=audio 32352 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
a=sendrecv
m=image 0 udptl t38
a=nortpproxy:yes
13:23:08.610 11/04/2011 (CALC) DBG: Failed to update call trace info.
Buffer Size exceeded. curlen 3408, len 1107
13:23:18.860 11/04/2011 [VRGEVPR] (EPT) INFO: ECAN changed to ECAN_OFF
for endpt 0
13:23:19.190 11/04/2011 [VRGEVPR] (CAS) DBG: Input event
'CLASSSTM_ONHOOK' 0xb
13:23:19.190 11/04/2011 [VRGEVPR] (CAS) DBG: Line 0: Old state =
stateClidTxNaIdle
13:23:19.190 11/04/2011 [VRGEVPR] (CAS) DBG: Line 0: New state =
stateClidTxNaIdle
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) DBG: evt: 0x1000, op1: 0, op2:
18, class: 0x1000
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) DBG: cmMapPhysEndptToCm: physEpt
0 already assigned to 0
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) INFO: CAS EVENT line 0 (ep 0):
CMEVT_ONHOOK
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) INFO: cmEndpt: 0, cid -1:
CMEVT_ONHOOK in CMST_TALK endpt state
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) INFO: cmCnxStateEngine: cid 5,
ep 0: CMCMD_RELEASE in CMST_CONNECTED callstate
13:23:19.190 11/04/2011 [VRGCMGR] (CMGR) INFO: cmStreamDelete: cid 5, ep
0, rtpcx 0, stream 0
13:23:19.190 11/04/2011 (CALC) INFO: Firewall disable rule: IP SIP_SERVER
(0x3e4dca15), mask 255.255.255.255 (0xffffffff), port 32352, transport 0.
13:23:19.190 11/04/2011 (CALC) INFO: Firewall disable rule: IP SIP_SERVER
(0x3e4dca15), mask 255.255.255.255 (0xffffffff), port 32353, transport 0.
13:23:19.190 11/04/2011 [VRGCMGR] (EPT) INFO: EnableRelay: VBD mode for
endpt 0
13:23:19.190 11/04/2011 [VRGCMGR] (EPT) INFO: DTMF Relay 0, Fax 1
13:23:19.190 11/04/2011 (SNMP) DBG: Taking ACTION for Event <259i>
13:23:19.190 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.200 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.200 11/04/2011 [SIG-LOG] (SIP) DBG: SIP >>>>> Sent 937 bytes
from 10.41.3.87:5060 to SIP_SERVER:5060 >>>>>
BYE sip:b2b-3612314441 at 127.0.0.1:5080 SIP/2.0
Via: SIP/2.0/UDP 10.41.3.87;branch=z9hG4bK84eb5822563c335d6
Route: <sip:SIP_SERVER;r2=on;lr=on;ftag=63ba74dc0e;nat=yes>
Route: <sip:127.0.0.1;r2=on;lr=on;ftag=63ba74dc0e;nat=yes>
Route:
<sip:127.0.0.1:5062;lr=on;ftag=63ba74dc0e;did=6cc.51132741;vsf=TmRYN3N5WFgzZ0pnd0U0dWR4Z0NOZFg3c3lYWDNnSmd3RTQ->
Proxy-Authorization: Digest
username="3628700025",realm="SIP_DOMAIN",nonce="TrPohU6z51nitoIt/8UE3ch1eVhnxJcJ",uri="sip:b2b-3612314441 at 127.0.0.1:5080",response="259c53ddfa817070d093cce6712162ac"
Max-Forwards: 70
From: <sip:3628700025 at SIP_DOMAIN>;tag=63ba74dc0e
To: <sip:0612314441 at SIP_DOMAIN:5060>;tag=7D2ED34A-4EB3E6A4000979A1-F5A0D700
Call-ID: c911c754909916ed
CSeq: 964430939 BYE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, PRACK, INFO
Supported: timer
User-Agent: Brcm-Callctrl/v1.10.3 M5T SIP Stack/4.1.2.2
Content-Length: 0
13:23:19.200 11/04/2011 (CALC) DBG: Failed to update call trace info.
Buffer Size exceeded. curlen 3408, len 937
13:23:19.210 11/04/2011 [SipAppCoreTrans] (CMGR) INFO: cmEventCallback:
evt 5, cid 5, sta -1, res 16, pkt 815e493c, str
13:23:19.210 11/04/2011 [VRGEVPR] (EPT) INFO: 'HAPINET_MODE' (0x30c2),
cnx:0, line:0, hdl:0x52, op1:0x0, op2:0x0
13:23:19.210 11/04/2011 (SNMP) DBG: Taking ACTION for Event <258i>
13:23:19.210 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.210 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.210 11/04/2011 (SNMP) DBG: Taking ACTION for Event <258i>
13:23:19.210 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.210 11/04/2011 [PLQT] (DNS) INFO: dnsLookupHostsByName called
for DNS_SERVER.
13:23:19.220 11/04/2011 [SIG-LOG] (SIP) DBG: SIP <<<<< Recv 349 bytes
from SIP_SERVER:5060 to 10.41.3.87:5060 <<<<<
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.41.3.87;branch=z9hG4bK84eb5822563c335d6;rport=5060
From: <sip:3628700025 at SIP_DOMAIN>;tag=63ba74dc0e
To: <sip:0612314441 at SIP_DOMAIN:5060>;tag=7D2ED34A-4EB3E6A4000979A1-F5A0D700
Call-ID: c911c754909916ed
CSeq: 964430939 BYE
Server: kamailio (3.1.3 (x86_64/linux))
Content-Length: 0
13:23:19.220 11/04/2011 [SIG-LOG] (SIP) DBG: SIP <<<<< Recv 524 bytes
from SIP_SERVER:5060 to 10.41.3.87:5060 <<<<<
SIP/2.0 200 OK
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=63ba74dc0e>
Record-Route: <sip:127.0.0.1;r2=on;lr=on;ftag=63ba74dc0e>
Record-Route: <sip:SIP_SERVER;r2=on;lr=on;ftag=63ba74dc0e>
Via: SIP/2.0/UDP 10.41.3.87;rport=5060;branch=z9hG4bK84eb5822563c335d6
From: <sip:3628700025 at SIP_DOMAIN>;tag=63ba74dc0e
To: <sip:0612314441 at SIP_DOMAIN:5060>;tag=7D2ED34A-4EB3E6A4000979A1-F5A0D700
Call-ID: c911c754909916ed
CSeq: 964430939 BYE
Server: Sipwise NGCP Application Server
Content-Length: 0
13:23:19.220 11/04/2011 (CALC) DBG: Failed to update call trace info.
Buffer Size exceeded. curlen 3759, len 524
13:23:19.230 11/04/2011 (CALC) INFO: SF: Deleting service flow, handle
0x815ddf58
13:23:19.230 11/04/2011 (CALC) INFO: SF: Internal map -> remove flow: 0x3,
0x0
13:23:19.240 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_DELETE_PROCESS]
13:23:19.240 11/04/2011 [VRGCMGR] (RTP) DBG: SetCurrentRTPStreamTx = (0).
13:23:19.240 11/04/2011 (CALC) INFO: CC: cnx 0 deletion completed.
13:23:19.240 11/04/2011 (CALC) INFO: cnx 0->[GWECNX_DELETED], ri=0
13:23:19.240 11/04/2011 (CALC) INFO: Firewall disable rule: IP 0.0.0.0
(0x0), mask 255.255.255.255 (0xffffffff), port 53456, transport 0.
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: -------------------------
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Endpt 0: Outgoing call
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Name: 0612314441
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: URI: 0612314441
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: CallID:
c911c754909916ed
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Start: 4/11/2011
13:20:35
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: End: 4/11/2011
13:23:19
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: CDR: 0x80c2be70
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: From:
10.41.3.87:53456
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: To: SIP_SERVER:32350
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (LOC):
PS=8132, OS=1301120, PR=7604, OR=1216640, PL=2462, JI=0, LA=15
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (REM):
RPS=7494, ROS=1199040, RPL=0, RJI=0
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-LOC):
NLR=0, JDR=0, BLD=0, GLD=0, BD=0, GD=0, RTD=40, ESD=49
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-LOC):
SL=-85, NL=-72, RERL=75, GMN=16, NSR=96, XSR=127, MLQ=44, MCQ=44
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-LOC):
PLC=0, JBA=3, JBR=0, JBN=0, JBM=5, JBS=200, IAJ=0
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-REM):
NLR=0, JDR=0, BLD=0, GLD=0, BD=0, GD=0, RTD=0, ESD=0
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-REM):
SL=0, NL=0, RERL=0, GMN=0, NSR=0, XSR=0, MLQ=0, MCQ=0
13:23:19.240 11/04/2011 [VRGCMGR] (CMGR) INFO: Stats (XR-REM):
PLC=0, JBA=0, JBR=0, JBN=0, JBM=0, JBS=0, IAJ=0
13:23:19.250 11/04/2011 [VRGCMGR] (CMGR) INFO: -------------------------
13:23:19.250 11/04/2011 (SNMP) DBG: mibUpdateMtaLastCallStats()
NextStatsCallTableSlot=2
13:23:19.470 11/04/2011 (SNMP) DBG: mibUpdateMtaLastCallStatsVendor()
NextStatsCallTable=0
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmCsaStateEngine: cid 5,
ep 0: CMEVT_CLEARED
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) DBG: Remove cid 5
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmTone: 0, EPSIG_NULL, 0 msec
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: Line 0 (3628700025): Idle
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmUnMapCmEndpt: Releasing
physEpt 0 from 0
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) DBG: evt: 0x1000, op1: 0, op2:
29, class: 0x1000
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmMapPhysEndptToCm:
Assigning physEndpt 0 to cmEndpt 0
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) DBG: evt: 0x3005, op1: 5, op2:
16, class: 0x3000
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmProcessCallEvent: cid
0x5, event 5 CCEVT_STATUS, reason 16 CCRSN_RELEND, packet 815e493c
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmCnxStateEngine: cid 5,
ep 0: CMEVT_CLEARED in CMST_CLEARING callstate
13:23:19.480 11/04/2011 [VRGCMGR] (CMGR) INFO: cmEndpt: 0, cid -1:
CMEVT_TERMINATED in CMST_ONHOOK endpt state
13:23:19.710 11/04/2011 [VRGEVPR] (EPT) INFO: ECAN changed to ECAN_ON for
endpt 0
13:23:19.710 11/04/2011 [VRGCMGR] (CMGR) DBG: evt: 0x1000, op1: 0, op2:
29, class: 0x1000
13:23:19.710 11/04/2011 [VRGCMGR] (CMGR) DBG: cmMapPhysEndptToCm: physEpt
0 already assigned to 0
13:23:19.850 11/04/2011 [VRGEVPR] (CAS) DBG: Input event
'CLASSSTM_OFFHOOK' 0xa
> Sounds to me more like a problem with session timers, if the calls are
> set up properly and audio is 2 way, then I wouldn't consider it a NAT
> issue.
> We've touched on session timers a few times here, I had an issue a month
> or two back. You can read all the archived posts in the user list...
> this has helped me immensely. Perhaps you should take a peek into those
> and maybe even post some logs of an example call.
>
> Regards,
> Jonathan S.
>
> On 11/07/2011 05:14 AM, � wrote:
>> Dear all,
>>
>> I would like to request your help regarding to may NAT issue.
>>
>> In case if the modem start the call (Thomson) to PSTN the line will be
>> closed after 2:30 minutes. Unfortunately we not have any
>> configure/access
>> possibility in the PSTN Gateway side.
>>
>> In any other case the server work perfect.
>>
>> Regards,
>> Árpád
>>
>>
>>
>> _______________________________________________
>> Spce-user mailing list
>> Spce-user at lists.sipwise.com
>> http://lists.sipwise.com/listinfo/spce-user
>
>
> _______________________________________________
> Spce-user mailing list
> Spce-user at lists.sipwise.com
> http://lists.sipwise.com/listinfo/spce-user
>
More information about the Spce-user
mailing list