[Partysip-dev] Almost-infinite message loop for Invite

[Gary Corcoran]

I'm a new user of partysip, trying to test and debug our SIP phone.
I installed partysip-0.5.3 and libosip-0.9.3 on my (private) FreeBSD
server, and setup DNS (named) on it.

I'm trying to call from one phone to another one on the same
domain (same server).  First, I register from the destination
phone, and it seems to work (see log).  Then I attempt to call
the registered phone, but I end up getting an (attempted) infinite
number of "Via"'s added as my server tries to forward the INVITE
to itself - it never sends the Invite out to the destination.

I saw the discussion from back in September about this type of
problem, and I saw that patches were added that supposedly address
this thing - but they don't seem to do anything for me!  ;-)
I run with '-d 6', and I added a bunch of extra debug messages,
and the beginning of my log is attached.  Due to the recursion,
it goes for over 10,000 lines before it stops or crashes, so this
is just the first 300 or so lines...

Any ideas?

BTW, a major stumbling block to even getting this far was the
fact that no one mentioned that I had to add lines for 'sip'
to /etc/services so that the host server lookup would succeed!
(else the "am I responsible for this domain" kept failing)

Thanks,
Gary

| INFO2 | <psp_core.c: 315> serverip token 0: '10.56.78.114'
| INFO2 | <psp_core.c: 270> servername token 0: 'gary.net'
| INFO1 | <main.c: 351> loading plugin: udp
| INFO1 | <main.c: 351> loading plugin: syntax
| INFO2 | <syntax_core.c: 48> syntax plugin: plugin_init()!
| INFO1 | <main.c: 351> loading plugin: filter
| INFO2 | <filter_core.c: 49> filter plugin: plugin_init()!
| INFO1 | <main.c: 351> loading plugin: auth
| INFO2 | <auth_core.c: 55> auth plugin: plugin_init()!
| INFO1 | <auth_core.c: 75> auth plugin: Authentication is turned off!
| INFO1 | <main.c: 351> loading plugin: rgstrar
| INFO2 | <rgstrar_core.c: 54> rgstrar plugin: plugin_init()!
| INFO1 | <main.c: 351> loading plugin: ls_localdb
| INFO2 | <ls_localdb_core.c: 46> ls_localdb plugin: plugin_init()!
| INFO1 | <ls_localdb.c: 108> ls_localdb plugin: configured to run in statefull 
mode!
| INFO1 | <main.c: 351> loading plugin: ls_sfull
| INFO2 | <ls_sfull_core.c: 52> ls_sfull plugin: plugin_init()!
| INFO2 | <psp_core.c: 428> starting the sfp module with the main thread
| INFO2 | <udp.c: 449> UDP MESSAGE RECEIVED
| INFO2 | <udp.c: 483> udp plugin: RCV UDP MESSAGE (from 10.56.78.151:1035)
| INFO1 | <udp.c: 491> 
REGISTER sip:registrar.gary.net:5060 SIP/2.0
From:BigGuy <sip:address@hidden>;tag=C6413030443037379D270000
To:LittleGuy <sip:address@hidden>;tag=1298674965
Contact:LittleGuy <sip:address@hidden>
Call-ID:address@hidden
CSeq:11 REGISTER
Expires:36000
Via:SIP/2.0/UDP 10.56.78.151:5060
Supported:100rel
Content-Length:0


| INFO2 | <../../fsm/transaction.c: 38> allocating transaction ressource 1 
01B227108281400000000000
| INFO2 | <../../fsm/nist.c: 32> allocating NIST context
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO1 | <psp_core4.c: 117> psp_core_cb_rcvregister!
| INFO2 | <imp.c: 260> imp module: wake up!
| INFO1 | <psp_req.c: 32> Allocating psp_req ressource!
| INFO2 | <syntax.c: 154> syntax plugin: Ip address detected!
| INFO1 | <filter.c: 372> filter plugin: entering cb_filter_search_location
| INFO1 | <filter.c: 484> filter plugin: Didn't do anything with this request?
| INFO2 | <rgstrar.c: 72> rgstrar plugin: Updating contact list of a user!
| INFO1 | <rgstrar.c: 160> INFO: rgstrar plugin: User Registration saved!
| INFO1 | <imp.c: 385> Swithing to uas mode!
| INFO2 | <uap.c: 225> uap module: wake up!
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO2 | <psp_core.c: 1104> Entered psp_core_cb_snd_message(), 
host='10.56.78.151', port=5060
| INFO2 | <psp_core.c: 1161> Using host='10.56.78.151', port=5060
| INFO1 | <udp.c: 674> 
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.56.78.151:5060
From: BigGuy <sip:address@hidden>;tag=C6413030443037379D270000
To: LittleGuy <sip:address@hidden>;tag=1298674965
Call-ID: address@hidden
CSeq: 11 REGISTER
Contact: LittleGuy <sip:address@hidden>;expires=36000
Content-Length: 0


| INFO1 | <udp.c: 745> udp_plugin: message sent to 10.56.78.151 on port 5060
| INFO1 | <psp_core4.c: 215> psp_core_cb_snd2xx!
| INFO2 | <udp.c: 449> UDP MESSAGE RECEIVED
| INFO2 | <udp.c: 483> udp plugin: RCV UDP MESSAGE (from 10.56.78.150:1040)
| INFO1 | <udp.c: 491> 
INVITE sip:address@hidden SIP/2.0
From:sip:10.56.78.150;tag=BD0A3030443037371CDD0200
To:sip:address@hidden
Content-Type:application/SDP
Call-ID:address@hidden
CSeq:1 INVITE
Expires:36000
Via:SIP/2.0/UDP 10.56.78.150:5060
Contact:<sip:10.56.78.150:5060>
Supported:100rel
Content-Length:330

v=0
o=garycor 1193046 3430008 IN IP4 10.56.78.150
s=-
c=IN IP4 10.56.78.150
t=0 0
m=audio 6842 RTP/AVP 96
a=rtpmap:96 PCMA/8000
a=ptime:60
m=audio 6842 RTP/AVP 97
a=rtpmap:97 G723/8000
a=ptime:60
m=audio 6842 RTP/AVP 98
a=rtpmap:98 PCMU/8000
a=ptime:60
m=audio 6842 RTP/AVP 99
a=rtpmap:99 X-G729a/8000
a=ptime:60

| INFO2 | <../../fsm/transaction.c: 38> allocating transaction ressource 2 
01B22755DC8140000000000A
| INFO2 | <../../fsm/ist.c: 32> allocating IST context
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO1 | <psp_core4.c: 92> psp_core_cb_rcvinvite!
| INFO2 | <psp_core.c: 1104> Entered psp_core_cb_snd_message(), 
host='10.56.78.150', port=5060
| INFO2 | <psp_core.c: 1161> Using host='10.56.78.150', port=5060
| INFO1 | <udp.c: 674> 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Content-Length: 0


| INFO1 | <udp.c: 745> udp_plugin: message sent to 10.56.78.150 on port 5060
| INFO1 | <psp_core4.c: 179> psp_core_cb_snd1xx!
| INFO2 | <imp.c: 260> imp module: wake up!
| INFO1 | <psp_req.c: 32> Allocating psp_req ressource!
| INFO2 | <syntax.c: 154> syntax plugin: Ip address detected!
| INFO1 | <filter.c: 372> filter plugin: entering cb_filter_search_location
| INFO1 | <filter.c: 484> filter plugin: Didn't do anything with this request?
| INFO2 | <ls_sfull.c: 190> ls_sfull plugin: checking if we are responsible for 
request-URI 'gary.net'
| INFO2 | <psp_core.c: 869> checking if responsible for uri->host='gary.net'
| INFO2 | <psp_core.c: 879> hostname is not IP addr, checking for servername(s)
| INFO2 | <psp_core.c: 885> servername[0]='gary.net'
| INFO2 | <psp_core.c: 924> host match found
| INFO1 | <ls_sfull.c: 197> ls_sfull plugin: ignore this request which belongs 
to this domain.
| INFO1 | <ls_localdb.c: 277> ls_localdb plugin: 1 locations found!
| INFO1 | <imp.c: 396> Swithing to sfull mode!
| INFO2 | <sfp.c: 419> sfp module: wake up!
| INFO2 | <ppldns.c: 435> About to ask for '_sip._udp.gary.net IN SRV'
| INFO2 | <ppldns.c: 453> Got valid response for query '_sip._udp.gary.net IN 
SRV'
| INFO2 | <ppldns.c: 514> Hostname 'gary.net' resolved to '10.56.78.114'
| INFO2 | <psp_resolv.c: 175> After querying dns for address='gary.net', 
name='gary.net': IP=114.78.56.10, port=50195
| INFO2 | <psp_resolv.c: 181> Changed port to 5060
| INFO2 | <psp_resolv.c: 196> Successfully resolved the domain 'gary.net' udp!
| INFO2 | <sfp.c: 419> sfp module: wake up!
| INFO2 | <../../fsm/transaction.c: 38> allocating transaction ressource 3 
01B22755DC8140000000000A
| INFO2 | <../../fsm/ict.c: 34> allocating ICT context
| INFO2 | <sfp.c: 1042> sfp module: The destination for the transaction is set 
to: '10.56.78.114'.!
| INFO2 | <sfp.c: 1125> sfp module: transaction correctly forwarded!
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO2 | <psp_core.c: 1104> Entered psp_core_cb_snd_message(), 
host='10.56.78.114', port=50195
| INFO2 | <psp_core.c: 1156> RequestMsg: port=50195, overriding: set to 5060
| INFO2 | <psp_core.c: 1161> Using host='10.56.78.114', port=5060
| INFO1 | <udp.c: 674> 
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Contact: <sip:10.56.78.150:5060>
expires: 36000
supported: 100rel
Content-Type: application/SDP
Content-Length: 330  

v=0
o=garycor 1193046 3430008 IN IP4 10.56.78.150
s=-
c=IN IP4 10.56.78.150
t=0 0
m=audio 6842 RTP/AVP 96
a=rtpmap:96 PCMA/8000
a=ptime:60
m=audio 6842 RTP/AVP 97
a=rtpmap:97 G723/8000
a=ptime:60
m=audio 6842 RTP/AVP 98
a=rtpmap:98 PCMU/8000
a=ptime:60
m=audio 6842 RTP/AVP 99
a=rtpmap:99 X-G729a/8000
a=ptime:60

| INFO1 | <udp.c: 745> udp_plugin: message sent to 10.56.78.114 on port 5060
| INFO1 | <psp_core5.c: 92> psp_core_cb_sndinvite!
| INFO2 | <udp.c: 449> UDP MESSAGE RECEIVED
| INFO2 | <udp.c: 483> udp plugin: RCV UDP MESSAGE (from 10.56.78.114:5060)
| INFO1 | <udp.c: 491> 
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Contact: <sip:10.56.78.150:5060>
expires: 36000
supported: 100rel
Content-Type: application/SDP
Content-Length: 330  

v=0
o=garycor 1193046 3430008 IN IP4 10.56.78.150
s=-
c=IN IP4 10.56.78.150
t=0 0
m=audio 6842 RTP/AVP 96
a=rtpmap:96 PCMA/8000
a=ptime:60
m=audio 6842 RTP/AVP 97
a=rtpmap:97 G723/8000
a=ptime:60
m=audio 6842 RTP/AVP 98
a=rtpmap:98 PCMU/8000
a=ptime:60
m=audio 6842 RTP/AVP 99
a=rtpmap:99 X-G729a/8000
a=ptime:60

| INFO2 | <../../fsm/transaction.c: 38> allocating transaction ressource 4 
01B22755DC8140000000000A
| INFO2 | <../../fsm/ist.c: 32> allocating IST context
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO1 | <psp_core4.c: 92> psp_core_cb_rcvinvite!
| INFO2 | <psp_core.c: 1104> Entered psp_core_cb_snd_message(), 
host='10.56.78.114', port=5060
| INFO2 | <psp_core.c: 1161> Using host='10.56.78.114', port=5060
| INFO1 | <udp.c: 674> 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Content-Length: 0


| INFO1 | <udp.c: 745> udp_plugin: message sent to 10.56.78.114 on port 5060
| INFO1 | <psp_core4.c: 179> psp_core_cb_snd1xx!
| INFO2 | <imp.c: 260> imp module: wake up!
| INFO1 | <psp_req.c: 32> Allocating psp_req ressource!
| INFO2 | <syntax.c: 154> syntax plugin: Ip address detected!
| INFO1 | <filter.c: 372> filter plugin: entering cb_filter_search_location
| INFO1 | <filter.c: 484> filter plugin: Didn't do anything with this request?
| INFO2 | <ls_sfull.c: 190> ls_sfull plugin: checking if we are responsible for 
request-URI 'gary.net'
| INFO2 | <psp_core.c: 869> checking if responsible for uri->host='gary.net'
| INFO2 | <psp_core.c: 879> hostname is not IP addr, checking for servername(s)
| INFO2 | <psp_core.c: 885> servername[0]='gary.net'
| INFO2 | <psp_core.c: 924> host match found
| INFO1 | <ls_sfull.c: 197> ls_sfull plugin: ignore this request which belongs 
to this domain.
| INFO1 | <ls_localdb.c: 277> ls_localdb plugin: 1 locations found!
| INFO1 | <imp.c: 396> Swithing to sfull mode!
| INFO2 | <udp.c: 449> UDP MESSAGE RECEIVED
| INFO2 | <udp.c: 483> udp plugin: RCV UDP MESSAGE (from 10.56.78.114:5060)
| INFO1 | <udp.c: 491> 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Content-Length: 0


| INFO2 | <sfp.c: 419> sfp module: wake up!
| INFO2 | <../../fsm/transaction.c: 38> allocating transaction ressource 5 
01B22755DC8140000000000A
| INFO2 | <../../fsm/ict.c: 34> allocating ICT context
| INFO2 | <sfp.c: 1042> sfp module: The destination for the transaction is set 
to: '10.56.78.114'.!
| INFO2 | <sfp.c: 1125> sfp module: transaction correctly forwarded!
| INFO2 | <psp_osip.c: 70> osip module: wake up!
| INFO1 | <psp_core5.c: 164> psp_core_cb_rcv1xx!
| INFO2 | <psp_core.c: 1104> Entered psp_core_cb_snd_message(), 
host='10.56.78.114', port=50195
| INFO2 | <psp_core.c: 1156> RequestMsg: port=50195, overriding: set to 5060
| INFO2 | <psp_core.c: 1161> Using host='10.56.78.114', port=5060
| INFO1 | <udp.c: 674> 
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf984ee50d09f7a6383e1f09ad2d307e69.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060
From: <sip:10.56.78.150>;tag=BD0A3030443037371CDD0200
To: <sip:address@hidden>
Call-ID: address@hidden
CSeq: 1 INVITE
Contact: <sip:10.56.78.150:5060>
expires: 36000
supported: 100rel
Content-Type: application/SDP
Content-Length: 330  

v=0
o=garycor 1193046 3430008 IN IP4 10.56.78.150
s=-
c=IN IP4 10.56.78.150
t=0 0
m=audio 6842 RTP/AVP 96
a=rtpmap:96 PCMA/8000
a=ptime:60
m=audio 6842 RTP/AVP 97
a=rtpmap:97 G723/8000
a=ptime:60
m=audio 6842 RTP/AVP 98
a=rtpmap:98 PCMU/8000
a=ptime:60
m=audio 6842 RTP/AVP 99
a=rtpmap:99 X-G729a/8000
a=ptime:60

| INFO1 | <udp.c: 745> udp_plugin: message sent to 10.56.78.114 on port 5060
| INFO1 | <psp_core5.c: 92> psp_core_cb_sndinvite!
| INFO2 | <udp.c: 449> UDP MESSAGE RECEIVED
| INFO2 | <udp.c: 483> udp plugin: RCV UDP MESSAGE (from 10.56.78.114:5060)
| INFO1 | <udp.c: 491> 
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf984ee50d09f7a6383e1f09ad2d307e69.0
Via: SIP/2.0/UDP 
10.56.78.114:5060;branch=z9hG4bKf71c7546dfcdac400d4cda063d7548c46.0
Via: SIP/2.0/UDP 10.56.78.150:5060