search

jack0402 / csipsimple

Automatically exported from code.google.com/p/csipsimple
0 stars 0 forks source link

Initial Register Repeating Twice #300

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Set up an account with Sipsorcery.

What is the expected output? What do you see instead?
The account shows registered in CSipSimple but it shows unregistered in 
Sipsorcery.

This only happens with the initial registration. Subsequent registration 
renewals work fine and Sipsorcery will show the account as registered. 

The SIP trace shows that CSipSimple repeats the Register process twice during 
the initial registration. The immediate second Register process is probably the 
cause that deregisters the first registration. However, Sipsorcery does OK the 
immediate second Register, but for some reason, it deregisters the client.

Subsequent registration renewals only do the Register process once for each 
renewal. So the account registers fine in subsequent registrations.

Test was done with CSipSimple version 0.00-15.

Original issue reported on code.google.com by jac...@gmail.com on 23 Oct 2010 at 6:02

GoogleCodeExporter commented 9 years ago 
CSipSimple relies on pjsip sip stack.
Pjsip guys implemented something cool to solve NAT + port changes without STUN. 
However it implies that the app register a first time and then deduce from the 
registration result a correct public IP and re-register.

That's why you see two 2 registrations. 
However, should be fine with the server : it first register, then unregister 
and then register again... unless the sip server doesn't behaves as it should 
regarding registrations it should register the last registration (all the more 
so as if you get the registration icon, it means that registration is 
acknoledge our last registration).

What you could try is to activate STUN (in settings > media > Enable STUN).
Not sure that it will solve the problem since it could still re-register if 
port change is needed, but it can help.

Original comment by r3gis...@gmail.com on 23 Oct 2010 at 7:57

GoogleCodeExporter commented 9 years ago 
Yes, the duplicate registrations should work fine because Sipsorcery OK'ed the 
second registration. I posted the issue on Sipsorcery forum before I posted 
here just in case. 

However, you described the process as register, unregister, register. While 
from the SIP trace，I did not notice the unregister process. More 
specifically, it was like this: 

Register(expires 300), Unauthorized, Register(expires 300), OK, 
Register(expires 300), Unauthorized, Register(expires 300), OK.

The STUN option does not seem to affect the behavior and result of Register.

Original comment by jac...@gmail.com on 23 Oct 2010 at 8:20

GoogleCodeExporter commented 9 years ago 
Aaron @Sipsorcery has identified the bug. The second Register process sends the 
registration with "expires=0" in the Contact header which overrules the 
"Expires" header, and that effectively unregisters the client. But there isn't 
a third Register process to register the client again until it is the time for 
the next registration renewal. 

Please take a look of the following thread,
http://forum.sipsorcery.com/viewtopic.php?f=6&t=2897&p=17305

Now the question is, the third Register process is missing, is it missing from 
CSipSimple or for some reason Sipsorcery does not receive it?

Original comment by jac...@gmail.com on 24 Oct 2010 at 5:39

GoogleCodeExporter commented 9 years ago 
Indeed at the end of the traces you sent csipsimple should send a last updated 
register.
Could you try to produce logs in csipsimple?
See how to collect logs wiki page.
With these logs we'll see the device point of view.

Original comment by r3gis...@gmail.com on 24 Oct 2010 at 6:22

GoogleCodeExporter commented 9 years ago 
The log shows the third Register was not sent out. See the last line stating 
the registration was successful. It follows immediately after the second 
Register (expires=0). 

======Log===============================
10-24 02:38:04.441 D/libpjsip(28477):  02:38:04.450    pjsua_acc.c  Account 
xxxxxxxx <sip:xxxxxxxx@sipsorcery.com> added with id 0
10-24 02:38:04.451 V/libpjsip(28477):  02:38:04.451       endpoint  Request msg 
REGISTER/cseq=25098 (tdta0x81fec0) created.
10-24 02:38:04.451 V/libpjsip(28477):  02:38:04.451    tsx0x611c0c  Transaction 
created for Request msg REGISTER/cseq=25099 (tdta0x81fec0)
10-24 02:38:04.451 V/libpjsip(28477):  02:38:04.452    tsx0x611c0c  Sending 
Request msg REGISTER/cseq=25099 (tdta0x81fec0) in state Null
10-24 02:38:04.451 V/libpjsip(28477):  02:38:04.452  sip_resolve.c  DNS 
resolver not available, target 'sipsorcery.com:0' type=TCP will be resolved 
with getaddrinfo()
10-24 02:38:04.741 V/libpjsip(28477):  02:38:04.746  sip_resolve.c  Target 
'sipsorcery.com:0' type=TCP resolved to '69.59.142.213:5060' type=TCP (TCP 
transport)
10-24 02:38:04.741 D/libpjsip(28477):  02:38:04.746   pjsua_core.c  TX 604 
bytes Request msg REGISTER/cseq=25099 (tdta0x81fec0) to tcp 69.59.142.213:5060:
10-24 02:38:04.741 D/libpjsip(28477): REGISTER sip:sipsorcery.com;transport=tcp 
SIP/2.0
10-24 02:38:04.741 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport;branch=z9hG4bKPjY0POr-9pxT1kDv7C3EbtE3iK4KoKpeCv
10-24 02:38:04.741 D/libpjsip(28477): Max-Forwards: 70
10-24 02:38:04.741 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=VIsRKR9MUVBqDkZCIa7VtzRTwidc8YdF
10-24 02:38:04.741 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:04.741 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:04.741 D/libpjsip(28477): CSeq: 25099 REGISTER
10-24 02:38:04.741 D/libpjsip(28477): User-Agent: CSipSimple
10-24 02:38:04.741 D/libpjsip(28477): Contact: "xxxxxxxx" 
<sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>
10-24 02:38:04.741 D/libpjsip(28477): Expires: 3600
10-24 02:38:04.741 D/libpjsip(28477): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
10-24 02:38:04.741 D/libpjsip(28477): Content-Length:  0
10-24 02:38:04.741 D/libpjsip(28477): 
10-24 02:38:04.741 D/libpjsip(28477): 
10-24 02:38:04.741 D/libpjsip(28477): --end msg--
10-24 02:38:04.741 V/libpjsip(28477):  02:38:04.747    tsx0x611c0c  State 
changed from Null to Calling, event=TX_MSG
10-24 02:38:04.741 I/libpjsip(28477):  02:38:04.748    pjsua_acc.c  
Registration sent
10-24 02:38:04.751 D/Dialer  (28477): Update chooser choice
10-24 02:38:04.841 D/SIP AccountList(28477): > Need to update list !
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.258 sip_endpoint.c  Processing 
incoming message: Response msg 401/REGISTER/cseq=25099 (rdata0x46c3e4)
10-24 02:38:05.253 D/libpjsip(28477):  02:38:05.258   pjsua_core.c  RX 543 
bytes Response msg 401/REGISTER/cseq=25099 (rdata0x46c3e4) from tcp 
69.59.142.213:5060:
10-24 02:38:05.253 D/libpjsip(28477): SIP/2.0 401 Unauthorised
10-24 02:38:05.253 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport=43602;branch=z9hG4bKPjY0POr-9pxT1kDv7C3EbtE3iK4KoKpeCv;r
eceived=xx.xx.xx.xx
10-24 02:38:05.253 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:05.253 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=VIsRKR9MUVBqDkZCIa7VtzRTwidc8YdF
10-24 02:38:05.253 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.253 D/libpjsip(28477): CSeq: 25099 REGISTER
10-24 02:38:05.253 D/libpjsip(28477): WWW-Authenticate: Digest 
realm="sipsorcery.com",nonce="20307226251063734110"
10-24 02:38:05.253 D/libpjsip(28477): Content-Length: 0
10-24 02:38:05.253 D/libpjsip(28477): Allow: ACK, BYE, CANCEL, INFO, INVITE, 
NOTIFY, OPTIONS, REFER, REGISTER, SUBSCRIBE
10-24 02:38:05.253 D/libpjsip(28477): 
10-24 02:38:05.253 D/libpjsip(28477): 
10-24 02:38:05.253 D/libpjsip(28477): --end msg--
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.258    tsx0x611c0c  Incoming 
Response msg 401/REGISTER/cseq=25099 (rdata0x46c3e4) in state Calling
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.259    tsx0x611c0c  State 
changed from Calling to Completed, event=RX_MSG
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.259    tsx0x5780fc  Transaction 
created for Request msg REGISTER/cseq=25100 (tdta0x81fec0)
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.259    tsx0x5780fc  Sending 
Request msg REGISTER/cseq=25100 (tdta0x81fec0) in state Null
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.259       endpoint  Request msg 
REGISTER/cseq=25100 (tdta0x81fec0): skipping target resolution because address 
is already set
10-24 02:38:05.253 D/libpjsip(28477):  02:38:05.259   pjsua_core.c  TX 791 
bytes Request msg REGISTER/cseq=25100 (tdta0x81fec0) to tcp 69.59.142.213:5060:
10-24 02:38:05.253 D/libpjsip(28477): REGISTER sip:sipsorcery.com;transport=tcp 
SIP/2.0
10-24 02:38:05.253 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport;branch=z9hG4bKPj5O3yPrxEPZF0qB-9VVjugVPV2Url0BtK
10-24 02:38:05.253 D/libpjsip(28477): Max-Forwards: 70
10-24 02:38:05.253 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=VIsRKR9MUVBqDkZCIa7VtzRTwidc8YdF
10-24 02:38:05.253 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:05.253 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.253 D/libpjsip(28477): CSeq: 25100 REGISTER
10-24 02:38:05.253 D/libpjsip(28477): User-Agent: CSipSimple
10-24 02:38:05.253 D/libpjsip(28477): Contact: "xxxxxxxx" 
<sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>
10-24 02:38:05.253 D/libpjsip(28477): Expires: 3600
10-24 02:38:05.253 D/libpjsip(28477): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
10-24 02:38:05.253 D/libpjsip(28477): Authorization: Digest 
username="xxxxxxxx", realm="sipsorcery.com", nonce="20307226251063734110", 
uri="sip:sipsorcery.com;transport=tcp", 
response="85aaa1f9816081b173dc12dc29261520"
10-24 02:38:05.253 D/libpjsip(28477): Content-Length:  0
10-24 02:38:05.253 D/libpjsip(28477): 
10-24 02:38:05.253 D/libpjsip(28477): 
10-24 02:38:05.253 D/libpjsip(28477): --end msg--
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x5780fc  State 
changed from Null to Calling, event=TX_MSG
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x611c0c  Timeout 
timer event
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x611c0c  State 
changed from Completed to Terminated, event=TIMER
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x611c0c  Timeout 
timer event
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x611c0c  State 
changed from Terminated to Destroyed, event=TIMER
10-24 02:38:05.253 V/libpjsip(28477):  02:38:05.260    tsx0x611c0c  Transaction 
destroyed!
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.464 sip_endpoint.c  Processing 
incoming message: Response msg 200/REGISTER/cseq=25100 (rdata0x46c3e4)
10-24 02:38:05.461 D/libpjsip(28477):  02:38:05.464   pjsua_core.c  RX 527 
bytes Response msg 200/REGISTER/cseq=25100 (rdata0x46c3e4) from tcp 
69.59.142.213:5060:
10-24 02:38:05.461 D/libpjsip(28477): SIP/2.0 200 Ok
10-24 02:38:05.461 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport=43602;branch=z9hG4bKPj5O3yPrxEPZF0qB-9VVjugVPV2Url0BtK;r
eceived=xx.xx.xx.xx
10-24 02:38:05.461 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=1222246502
10-24 02:38:05.461 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=VIsRKR9MUVBqDkZCIa7VtzRTwidc8YdF
10-24 02:38:05.461 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.461 D/libpjsip(28477): CSeq: 25100 REGISTER
10-24 02:38:05.461 D/libpjsip(28477): Contact: 
<sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=3600
10-24 02:38:05.461 D/libpjsip(28477): Date: Sun, 24 Oct 2010 06:37:51 GMT
10-24 02:38:05.461 D/libpjsip(28477): Content-Length: 0
10-24 02:38:05.461 D/libpjsip(28477): Server: www.sipsorcery.com
10-24 02:38:05.461 D/libpjsip(28477): 
10-24 02:38:05.461 D/libpjsip(28477): 
10-24 02:38:05.461 D/libpjsip(28477): --end msg--
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.465    tsx0x5780fc  Incoming 
Response msg 200/REGISTER/cseq=25100 (rdata0x46c3e4) in state Calling
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.465    tsx0x5780fc  State 
changed from Calling to Completed, event=RX_MSG
10-24 02:38:05.461 I/libpjsip(28477):  02:38:05.465    pjsua_acc.c  IP address 
change detected for account 0 (192.168.1.131:5060 --> xx.xx.xx.xx:43602). 
Updating registration (using method 2)
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.466       endpoint  Request msg 
REGISTER/cseq=25100 (tdta0x4b24f0) created.
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.466    tsx0x45dda4  Transaction 
created for Request msg REGISTER/cseq=25101 (tdta0x4b24f0)
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.467    tsx0x45dda4  Sending 
Request msg REGISTER/cseq=25101 (tdta0x4b24f0) in state Null
10-24 02:38:05.461 V/libpjsip(28477):  02:38:05.467  sip_resolve.c  DNS 
resolver not available, target 'sipsorcery.com:0' type=TCP will be resolved 
with getaddrinfo()
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.754  sip_resolve.c  Target 
'sipsorcery.com:0' type=TCP resolved to '69.59.142.213:5060' type=TCP (TCP 
transport)
10-24 02:38:05.751 D/libpjsip(28477):  02:38:05.754   pjsua_core.c  TX 678 
bytes Request msg REGISTER/cseq=25101 (tdta0x4b24f0) to tcp 69.59.142.213:5060:
10-24 02:38:05.751 D/libpjsip(28477): REGISTER sip:sipsorcery.com;transport=tcp 
SIP/2.0
10-24 02:38:05.751 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport;branch=z9hG4bKPjqPc4b.6TQm.Wf1cOwW63B4Nd9fVUhXd8
10-24 02:38:05.751 D/libpjsip(28477): Max-Forwards: 70
10-24 02:38:05.751 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=B40XJxsmT1weNpHkCqHLWyd2qLMNFqz1
10-24 02:38:05.751 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:05.751 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.751 D/libpjsip(28477): CSeq: 25101 REGISTER
10-24 02:38:05.751 D/libpjsip(28477): User-Agent: CSipSimple
10-24 02:38:05.751 D/libpjsip(28477): Contact: 
<sip:xxxxxxxx@xx.xx.xx.xx:43602;transport=tcp>
10-24 02:38:05.751 D/libpjsip(28477): Contact: "xxxxxxxx" 
<sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=0
10-24 02:38:05.751 D/libpjsip(28477): Expires: 3600
10-24 02:38:05.751 D/libpjsip(28477): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
10-24 02:38:05.751 D/libpjsip(28477): Content-Length:  0
10-24 02:38:05.751 D/libpjsip(28477): 
10-24 02:38:05.751 D/libpjsip(28477): 
10-24 02:38:05.751 D/libpjsip(28477): --end msg--
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.755    tsx0x45dda4  State 
changed from Null to Calling, event=TX_MSG
10-24 02:38:05.751 I/libpjsip(28477):  02:38:05.755    pjsua_acc.c  
Registration sent
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756    tsx0x5780fc  Timeout 
timer event
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756    tsx0x5780fc  State 
changed from Completed to Terminated, event=TIMER
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756    tsx0x5780fc  Timeout 
timer event
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756    tsx0x5780fc  State 
changed from Terminated to Destroyed, event=TIMER
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756   tdta0x81fec0  Destroying 
txdata Request msg REGISTER/cseq=25100 (tdta0x81fec0)
10-24 02:38:05.751 V/libpjsip(28477):  02:38:05.756    tsx0x5780fc  Transaction 
destroyed!
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.977 sip_endpoint.c  Processing 
incoming message: Response msg 401/REGISTER/cseq=25101 (rdata0x46c3e4)
10-24 02:38:05.972 D/libpjsip(28477):  02:38:05.977   pjsua_core.c  RX 543 
bytes Response msg 401/REGISTER/cseq=25101 (rdata0x46c3e4) from tcp 
69.59.142.213:5060:
10-24 02:38:05.972 D/libpjsip(28477): SIP/2.0 401 Unauthorised
10-24 02:38:05.972 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport=43602;branch=z9hG4bKPjqPc4b.6TQm.Wf1cOwW63B4Nd9fVUhXd8;r
eceived=xx.xx.xx.xx
10-24 02:38:05.972 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:05.972 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=B40XJxsmT1weNpHkCqHLWyd2qLMNFqz1
10-24 02:38:05.972 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.972 D/libpjsip(28477): CSeq: 25101 REGISTER
10-24 02:38:05.972 D/libpjsip(28477): WWW-Authenticate: Digest 
realm="sipsorcery.com",nonce="20307226251648140053"
10-24 02:38:05.972 D/libpjsip(28477): Content-Length: 0
10-24 02:38:05.972 D/libpjsip(28477): Allow: ACK, BYE, CANCEL, INFO, INVITE, 
NOTIFY, OPTIONS, REFER, REGISTER, SUBSCRIBE
10-24 02:38:05.972 D/libpjsip(28477): 
10-24 02:38:05.972 D/libpjsip(28477): 
10-24 02:38:05.972 D/libpjsip(28477): --end msg--
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.977    tsx0x45dda4  Incoming 
Response msg 401/REGISTER/cseq=25101 (rdata0x46c3e4) in state Calling
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.977    tsx0x45dda4  State 
changed from Calling to Completed, event=RX_MSG
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.977    tsx0x674c8c  Transaction 
created for Request msg REGISTER/cseq=25102 (tdta0x4b24f0)
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.977    tsx0x674c8c  Sending 
Request msg REGISTER/cseq=25102 (tdta0x4b24f0) in state Null
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.978       endpoint  Request msg 
REGISTER/cseq=25102 (tdta0x4b24f0): skipping target resolution because address 
is already set
10-24 02:38:05.972 D/libpjsip(28477):  02:38:05.978   pjsua_core.c  TX 865 
bytes Request msg REGISTER/cseq=25102 (tdta0x4b24f0) to tcp 69.59.142.213:5060:
10-24 02:38:05.972 D/libpjsip(28477): REGISTER sip:sipsorcery.com;transport=tcp 
SIP/2.0
10-24 02:38:05.972 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport;branch=z9hG4bKPji7itted.oxGtE9TjBJwT96Kb.a-jLGCt
10-24 02:38:05.972 D/libpjsip(28477): Max-Forwards: 70
10-24 02:38:05.972 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=B40XJxsmT1weNpHkCqHLWyd2qLMNFqz1
10-24 02:38:05.972 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>
10-24 02:38:05.972 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:05.972 D/libpjsip(28477): CSeq: 25102 REGISTER
10-24 02:38:05.972 D/libpjsip(28477): User-Agent: CSipSimple
10-24 02:38:05.972 D/libpjsip(28477): Contact: 
<sip:xxxxxxxx@xx.xx.xx.xx:43602;transport=tcp>
10-24 02:38:05.972 D/libpjsip(28477): Contact: "xxxxxxxx" 
<sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=0
10-24 02:38:05.972 D/libpjsip(28477): Expires: 3600
10-24 02:38:05.972 D/libpjsip(28477): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
10-24 02:38:05.972 D/libpjsip(28477): Authorization: Digest 
username="xxxxxxxx", realm="sipsorcery.com", nonce="20307226251648140053", 
uri="sip:sipsorcery.com;transport=tcp", 
response="426dd268e71cc9a08b554396ada594dc"
10-24 02:38:05.972 D/libpjsip(28477): Content-Length:  0
10-24 02:38:05.972 D/libpjsip(28477): 
10-24 02:38:05.972 D/libpjsip(28477): 
10-24 02:38:05.972 D/libpjsip(28477): --end msg--
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x674c8c  State 
changed from Null to Calling, event=TX_MSG
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x45dda4  Timeout 
timer event
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x45dda4  State 
changed from Completed to Terminated, event=TIMER
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x45dda4  Timeout 
timer event
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x45dda4  State 
changed from Terminated to Destroyed, event=TIMER
10-24 02:38:05.972 V/libpjsip(28477):  02:38:05.979    tsx0x45dda4  Transaction 
destroyed!
10-24 02:38:06.181 V/libpjsip(28477):  02:38:06.183 sip_endpoint.c  Processing 
incoming message: Response msg 200/REGISTER/cseq=25102 (rdata0x46c3e4)
10-24 02:38:06.181 D/libpjsip(28477):  02:38:06.184   pjsua_core.c  RX 451 
bytes Response msg 200/REGISTER/cseq=25102 (rdata0x46c3e4) from tcp 
69.59.142.213:5060:
10-24 02:38:06.181 D/libpjsip(28477): SIP/2.0 200 Ok
10-24 02:38:06.181 D/libpjsip(28477): Via: SIP/2.0/TCP 
xx.xx.xx.xx:43602;rport=43602;branch=z9hG4bKPji7itted.oxGtE9TjBJwT96Kb.a-jLGCt;r
eceived=xx.xx.xx.xx
10-24 02:38:06.181 D/libpjsip(28477): To: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=1719811563
10-24 02:38:06.181 D/libpjsip(28477): From: "xxxxxxxx" 
<sip:xxxxxxxx@sipsorcery.com>;tag=B40XJxsmT1weNpHkCqHLWyd2qLMNFqz1
10-24 02:38:06.181 D/libpjsip(28477): Call-ID: QDGulhRgvkOfmTiQqsLUjbWeaZ.Ms9Qx
10-24 02:38:06.181 D/libpjsip(28477): CSeq: 25102 REGISTER
10-24 02:38:06.181 D/libpjsip(28477): Date: Sun, 24 Oct 2010 06:37:51 GMT
10-24 02:38:06.181 D/libpjsip(28477): Content-Length: 0
10-24 02:38:06.181 D/libpjsip(28477): Server: www.sipsorcery.com
10-24 02:38:06.181 D/libpjsip(28477): 
10-24 02:38:06.181 D/libpjsip(28477): 
10-24 02:38:06.181 D/libpjsip(28477): --end msg--
10-24 02:38:06.181 V/libpjsip(28477):  02:38:06.184    tsx0x674c8c  Incoming 
Response msg 200/REGISTER/cseq=25102 (rdata0x46c3e4) in state Calling
10-24 02:38:06.181 V/libpjsip(28477):  02:38:06.184    tsx0x674c8c  State 
changed from Calling to Completed, event=RX_MSG
10-24 02:38:06.181 I/libpjsip(28477):  02:38:06.184    pjsua_acc.c  xxxxxxxx 
<sip:xxxxxxxx@sipsorcery.com>: registration success, status=200 (Ok), will 
re-register in 3600 seconds
=====End of Log========================

Original comment by jac...@gmail.com on 24 Oct 2010 at 6:58

GoogleCodeExporter commented 9 years ago 
The last register is not an Expires 0... It's :
Contact: <sip:xxxxxxxx@xx.xx.xx.xx:43602;transport=tcp>
Contact: "xxxxxxxx" <sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=0
Expires: 3600

Expires is 3600 => it also update the expires of latest local register to 0... 
But actually it is 3600 ! it applies for the contact 
<sip:xxxxxxxx@xx.xx.xx.xx:43602;transport=tcp> (the first contact in the list).

This one is not present in the trace you posted on sipsorcery forum.

Why this last one is not transmitted to the server... that's the question.

Or more likely it's the first contact header that is eaten by the server. I'm 
not a SIP specialist (all sip stuff are done by pjsip guys), 
but I think that as in HTTP mutiple header fields with the same name should be 
allowed by the server.
So here if what you get on sip sorcery traces :
Contact: "xxxxxxxx" <sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=0
Max-Forwards: 69
User-Agent: CSipSimple
Expires: 300

Correspond to what I send :
Contact: <sip:xxxxxxxx@xx.xx.xx.xx:43602;transport=tcp>
Contact: "xxxxxxxx" <sip:xxxxxxxx@192.168.1.131:5060;transport=TCP>;expires=0
Expires: 3600

There is a missing contact header that does the difference ! 

(Thanks to your logs I've understood a bug open times ago but that is 
absolutely not related ;) -- about callerID ;) ).

I've tested with an OpenSIP server and it works properly with 2 contact header 
field. 

Last question, (just for my information), I guess you are using Advanced or 
Expert account. Are you using SIP Proxy field or Force contact field? (Well 
force contact should solve your problem.. but will implies you already know 
your public IP... so not a good solution).

Just if you could do a test having a look at the same time to sipsorcery and 
csipsimple logs, checking CSeq ids to check that the last REGISTER sent has its 
first contact eaten by sipsorcery server... I think that it should be reported 
to sip sorcery guys. If they say that's not a standard way (not accepted by 
RFC) to send contact field I'll report back to pjsip guys to ask them why they 
are doing something not written in RFC.
SipSorcery guys maybe only manage comma separated contact field, but my 
understand of the RFC is that this *is* the exception while expanded 2 contact 
entries is normal.... but I can misunderstood, again I'm not a sip specialist 
and I've just waking up ;) .
*If I'm right*, they should really consider making their server support 
multiple fields entries with same names, else their server doesn't respect SIP 
RFC.

Keep me in touch.
(I reopen the bug in case it's in pjsip side that there is something wrong or 
something I can do on my side to provide an option for making it comma 
separated).

Original comment by r3gis...@gmail.com on 24 Oct 2010 at 9:07

GoogleCodeExporter commented 9 years ago 
You have a very good point. I did new trace logs on both sides of CSipSimple 
and Sipsorcery, and verified that Sipsorcery does eat the first Contact header 
of the two in the second Register. I will report the issue to Sipsorcery. Aaron 
should be able to fix the issue or give a good explanation if his 
implementation is more "standard". 

I did not use the SIP Proxy field unless the provider requires it. I did not 
use the Force contact either because the IP of the wireless data is dynamic. 
I'll keep you updated.

Original comment by jac...@gmail.com on 24 Oct 2010 at 4:35

GoogleCodeExporter commented 9 years ago 
@jack : Aaron has updated the sipsorcery software. Could you try to see if it's 
better now?

Let us know (here or on sipsorcery forum, I've created a forum account to be 
able to talk directly to sipsorcery support if needed ;) ).

Thx a lot for reporting that point.

Original comment by r3gis...@gmail.com on 31 Oct 2010 at 2:00

GoogleCodeExporter commented 9 years ago 
I just tried it and took a look at the SIP trace. I can confirm it has been 
fixed. Thanks for pursuing on the issue and the great job done @CSipSimple.

Original comment by jac...@gmail.com on 31 Oct 2010 at 5:21