Re: pb with jain-sip-presence-proxy : 500 Server Internal Error

Jean-Luc <[email protected]> Thu, 31 May 2007 13:28:25 +0000 (UTC)
Newsgroups gmane.comp.voip.nist-sip
Message-ID <[email protected]>
M. (Neo-Ranga) Ranganathan <mranga <at> gmail.com> writes:

> 
> Hi Jean-Luc,
> 
> Please look in the debug log.
> 
> Ranga
> 

Bonjour Ranga,

Thank you for your answer, i give you at the bottom of this mail an extract of 
the file "debug_log.txt" concerning the problem
i hope you can help me with this ...

When i track the error (500 server internal error) with Eclipse, i find that 
the code which generates the error is in the following lines (in the 

class  "RequestForwarding.java") :

  176    ...
  177    String stackIPAddress = sipStack.getIPAddress();
  178
  179    ListeningPoint lp = sipProvider.getListeningPoint();
  180    if (statefullForwarding) {
  181        SipURI sipURI = addressFactory.createSipURI(null,
  182                stackIPAddress);
  183    ...

   Comments about this :
a) line 177 : after the execution of this line, the value of stackIPAddress 
is "null" ?!
b) line 179 : the method getListeningPoint is deprecated, what's the pb ? Is it 
normal ?
c) line 181 et 182 : when this is executed, the error is generated (500 server 
internal error)
   perphaps because stackIPAddress is null ? 

very kind of you if you can find the pb ...

PS :to understand (at least a little) the JAIN-SIP-PRESENCE-PROXY code, do you 
know a doc well detailed ?

Sorry for my english, and thank you very much for all ...

Jean-Luc


Extract of the debug log :

DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:221) [UDPMessageChannel: peerAddress = 
192.168.18.63/5060]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:225) [Length = 919]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:227) [INVITE sip:sirejl@flaviol SIP/2.0
Via: SIP/2.0/UDP 192.168.18.63:5060;rport;branch=z9hG4bK110597597
From: <sip:coltranej@flaviol>;tag=2100108759
To: <sip:sirejl@flaviol>
Call-ID: [email protected]
CSeq: 20 INVITE
Contact: <sip:[email protected]:5060>
Max-Forwards: 5
User-Agent: Linphone-1.6.0/eXosip
Subject: Phone call
Expires: 120
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE
Content-Type: application/sdp
Content-Length:   428

v=0
o=coltranej 123456 654321 IN IP4 192.168.18.63
s=A conversation
c=IN IP4 192.168.18.63
t=0 0
m=audio 7078 RTP/AVP 111 110 0 3 8 101
a=rtpmap:111 speex/16000/1
a=rtpmap:110 speex/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:3 GSM/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
m=video 9078 RTP/AVP 98 99
a=rtpmap:98 H263-1998/90000
a=fmtp:98 CIF=1;QCIF=1
a=rtpmap:99 MP4V-ES/90000
]
DEBUG - gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:312) [ ]]>]
DEBUG - gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:313) 
[</debug>]
DEBUG - gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:314) 
[<message
from="192.168.18.63:5060" 
to="192.168.18.64:5060" 
time="1180600923242" 
isSender="false" 
transactionId="z9hg4bk110597597" 
callId="[email protected]" 
firstLine="INVITE sip:sirejl@flaviol SIP/2.0" 
debugLine="315" 
>
<![CDATA[INVITE sip:sirejl@flaviol SIP/2.0
Via: SIP/2.0/UDP 192.168.18.63:5060;rport;branch=z9hG4bK110597597
From: <sip:coltranej@flaviol>;tag=2100108759
To: <sip:sirejl@flaviol>
Call-ID: [email protected]
CSeq: 20 INVITE
Contact: <sip:[email protected]:5060>
Max-Forwards: 5
User-Agent: Linphone-1.6.0/eXosip
Subject: Phone call
Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,SUBSCRIBE,NOTIFY,MESSAGE
Content-Type: application/sdp
Content-Length: 428

]]>
</message>
]
DEBUG - gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:315) 
[<debug>]
DEBUG - gov.nist.javax.sip.stack.ServerLog.logMessage(ServerLog.java:316) [<!
[CDATA[ ]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction
(SIPTransactionStack.java:723) [looking for pending tx for 

:z9hg4bk110597597]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction.<init>
(SIPServerTransaction.java:419) [Creating Server Transactionnull]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[SIPServerTransaction.java:421][SIPTransactionStack.java:1007]

[SIPTransactionStack.java:829][UDPMessageChannel.java:370][Thread.java:595]]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest
(SIPTransaction.java:384) [Setting Branch id : z9hG4bK110597597]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.newSIPServerRequest
(SIPTransactionStack.java:844) [newSIPServerRequest( 

INVITE:z9hG4bK110597597):gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.NistSipMessageFactoryImpl.newSIPServerRequest
(NistSipMessageFactoryImpl.java:62) [Returning request interface for INVITE 

sip:sirejl@flaviol SIP/2.0
 gov.nist.javax.sip.DialogFilter@41d05d messageChannel = 
gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.acquireSem
(SIPTransaction.java:1078) [acquireSem 

[[[[gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[SIPTransaction.java:1079][SIPTransactionStack.java:854]

[UDPMessageChannel.java:370][Thread.java:595]]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:393) [About to process INVITE sip:sirejl@flaviol SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest
(SIPServerTransaction.java:623) [processRequest: INVITE sip:sirejl@flaviol 

SIP/2.0
]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction.processRequest
(SIPServerTransaction.java:625) [tx state = null]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.setOriginalRequest
(SIPTransaction.java:384) [Setting Branch id : z9hG4bK110597597]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.setState
(SIPTransaction.java:504) [Transaction:setState Trying Transaction 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 branchID = 
z9hG4bK110597597 isClient = false]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[SIPTransaction.java:507][SIPServerTransaction.java:1311]

[SIPServerTransaction.java:635][UDPMessageChannel.java:397][Thread.java:595]]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.setPassToListener
(SIPTransaction.java:1125) [setPassToListener()]
DEBUG - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:69) 
[PROCESSING INCOMING REQUEST INVITE sip:sirejl@flaviol SIP/2.0
Via: SIP/2.0/UDP 192.168.18.63:5060;rport;branch=z9hG4bK110597597
From: <sip:coltranej@flaviol>;tag=2100108759
To: <sip:sirejl@flaviol>
Call-ID: [email protected]
CSeq: 20 INVITE
Contact: <sip:[email protected]:5060>
Max-Forwards: 5
User-Agent: Linphone-1.6.0/eXosip
Subject: Phone call
Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,SUBSCRIBE,NOTIFY,MESSAGE
Content-Type: application/sdp
Content-Length: 428

v=0
o=coltranej 123456 654321 IN IP4 192.168.18.63
s=A conversation
c=IN IP4 192.168.18.63
t=0 0
m=audio 7078 RTP/AVP 111 110 0 3 8 101
a=rtpmap:111 speex/16000/1
a=rtpmap:110 speex/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:3 GSM/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
m=video 9078 RTP/AVP 98 99
a=rtpmap:98 H263-1998/90000
a=fmtp:98 CIF=1;QCIF=1
a=rtpmap:99 MP4V-ES/90000
 transactionChannel = gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 
listening point = 192.168.18.64:5060]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.getDialog
(SIPTransactionStack.java:491) [getDialog

([email protected]:sirejl@flaviol:coltranej@flaviol:2100108759) : 
returning null]
DEBUG - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:138) 
[dialogId = 

[email protected]:sirejl@flaviol:coltranej@flaviol:2100108759]
DEBUG - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:139) 
[dialog = null]
DEBUG - gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:621) 
[INVITE transaction.isMapped = false]
DEBUG - gov.nist.javax.sip.SipProviderImpl.handleEvent
(SipProviderImpl.java:102) [handleEvent javax.sip.RequestEvent

[source=gov.nist.javax.sip.SipProviderImpl@110fe28]currentTransaction = 
gov.nist.javax.sip.stack.SIPServerTransaction@70900d91this.sipListener = 

[email protected] = 
gov.nist.javax.sip.SipProviderImpl@110fe28]
DEBUG - gov.nist.javax.sip.SipProviderImpl.handleEvent
(SipProviderImpl.java:109) [Dialog = null]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[SipProviderImpl.java:114][DialogFilter.java:834]
[SIPServerTransaction.java:731]

[UDPMessageChannel.java:397][Thread.java:595]]
DEBUG - gov.nist.javax.sip.EventScanner.addEvent(EventScanner.java:54) 
[addEvent gov.nist.javax.sip.EventWrapper@d6a05e]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.run
(UDPMessageChannel.java:407) [Done processing INVITE sip:sirejl@flaviol SIP/2.0
/gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.EventScanner.run(EventScanner.java:400) [Processing 
gov.nist.javax.sip.EventWrapper@d6a05enevents 1]
DEBUG - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:87) 
[sipEvent = javax.sip.RequestEvent

[source=gov.nist.javax.sip.SipProviderImpl@110fe28]source = 
gov.nist.javax.sip.SipProviderImpl@110fe28]
DEBUG - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:105) 
[deliverEvent : INVITE sip:sirejl@flaviol SIP/2.0
 transaction gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 
sipEvent.serverTx = null]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction
(SIPTransactionStack.java:613) [serverTx: looking for key z9hg4bk110597597 

existing=
{z9hg4bk1941015899=gov.nist.javax.sip.stack.SIPServerTransaction@ffd0b528, 

z9hg4bk765215775=gov.nist.javax.sip.stack.SIPServerTransaction@f47f88d6}]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.findPendingTransaction
(SIPTransactionStack.java:723) [looking for pending tx for 

:z9hg4bk110597597]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.putPendingTransaction
(SIPTransactionStack.java:1222) [putPendingTransaction: 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:154) 
[Calling listener INVITE sip:sirejl@flaviol SIP/2.0
]
DEBUG - gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:158) 
[Calling listener gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - 
****************************************************
Request INVITE received:
INVITE sip:sirejl@flaviol SIP/2.0
Via: SIP/2.0/UDP 192.168.18.63:5060;rport;branch=z9hG4bK110597597
From: <sip:coltranej@flaviol>;tag=2100108759
To: <sip:sirejl@flaviol>
Call-ID: [email protected]
CSeq: 20 INVITE
Contact: <sip:[email protected]:5060>
Max-Forwards: 5
User-Agent: Linphone-1.6.0/eXosip
Subject: Phone call
Expires: 120
Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,SUBSCRIBE,NOTIFY,MESSAGE
Content-Type: application/sdp
Content-Length: 428

v=0
o=coltranej 123456 654321 IN IP4 192.168.18.63
s=A conversation
c=IN IP4 192.168.18.63
t=0 0
m=audio 7078 RTP/AVP 111 110 0 3 8 101
a=rtpmap:111 speex/16000/1
a=rtpmap:110 speex/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:3 GSM/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
m=video 9078 RTP/AVP 98 99
a=rtpmap:98 H263-1998/90000
a=fmtp:98 CIF=1;QCIF=1
a=rtpmap:99 MP4V-ES/90000

DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.isDialogCreated
(SIPTransactionStack.java:363) [isDialogCreated : INVITE returning true]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.findTransaction
(SIPTransactionStack.java:613) [serverTx: looking for key z9hg4bk110597597 

existing=
{z9hg4bk1941015899=gov.nist.javax.sip.stack.SIPServerTransaction@ffd0b528, 

z9hg4bk765215775=gov.nist.javax.sip.stack.SIPServerTransaction@f47f88d6}]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.addTransaction
(SIPTransactionStack.java:1093) [added transaction 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction$SendTrying.<init>
(SIPServerTransaction.java:239) [scheduled timer for 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.removePendingTransaction
(SIPTransactionStack.java:740) [removePendingTx: z9hg4bk110597597]
DEBUG - gov.nist.javax.sip.stack.SIPTransactionStack.addTransactionHash
(SIPTransactionStack.java:1115) [ putTransactionHash :  key = 

z9hg4bk110597597]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction$TransactionTimer.<init>
(SIPServerTransaction.java:272) [TransactionTimer() : z9hg4bk110597597]
DEBUG - Proxy, processRequest(), we are responsible for the domain... Let's 
find the contact...
DEBUG - Proxy, processRequest(), we canonicalized the request-URI
DEBUG - Proxy, processRequest(), the target set is the set of the contacts URI 
from the  location service
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.setState
(SIPTransaction.java:504) [Transaction:setState Completed Transaction 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 branchID = 
z9hG4bK110597597 isClient = false]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[SIPTransaction.java:507][SIPServerTransaction.java:1311]

[SIPServerTransaction.java:842][SIPServerTransaction.java:1264][null:-1][null:-
1][EventScanner.java:162][EventScanner.java:404][Thread.java:595]]
DEBUG - gov.nist.javax.sip.stack.SIPTransaction.enableTimeoutTimer
(SIPTransaction.java:558) [enableTimeoutTimer 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 tickCount 64 
currentTickCount = -1]
DEBUG - gov.nist.javax.sip.stack.SIPServerTransaction.sendMessage
(SIPServerTransaction.java:940) [sendMessage : tx = 

gov.nist.javax.sip.stack.SIPServerTransaction@70900d91 getState = Completed 
Transaction]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.<init>
(UDPMessageChannel.java:169) [Creating message channel 192.168.18.63/5060]
DEBUG - gov.nist.core.LogWriter.logStackTrace(LogWriter.java:101) 
[[UDPMessageChannel.java:509][SIPServerTransaction.java:396]

[SIPServerTransaction.java:945][SIPServerTransaction.java:1264][null:-1][null:-
1][EventScanner.java:162][EventScanner.java:404][Thread.java:595]]
DEBUG - gov.nist.javax.sip.stack.UDPMessageChannel.sendMessage
(UDPMessageChannel.java:609) 
[gov.nist.javax.sip.stack.UDPMessageChannel:sendMessage 

192.168.18.63/5060
SIP/2.0 500 Server Internal Error
Via: SIP/2.0/UDP 192.168.18.63:5060;rport;branch=z9hG4bK110597597
From: <sip:coltranej@flaviol>;tag=2100108759
To: <sip:sirejl@flaviol>
Call-ID: [email protected]
CSeq: 20 INVITE
Content-Length: 0