#442 Set PJSIP_CHECK_VIA_SENT_BY to 0

[Anonymous]

Originally created by: fander...@gmail.com
Originally owned by: r3gis...@gmail.com

Greetings!  A big thank you to all your efforts on cSipSimple, it's a really excellent program.  The only problem I'm having so far is that registration with the SIP server (callcentric.com) is not very stable even when the network connection seems (?) to be.

Using cSipSimple 0.00-15 on an HTC Wildfire running CyanogenMod 6.1-RC, WiFi only (no 3G/mobile data). WiFi Sleep Policy is set to Never.  Had to enable the "Stay Awake While On Call" and "Use Partial Wake Lock" options in order to prevent audio failing during a call when the screen blanks, and permanent loss of registration in sleep mode, respectively.  (The first problem, and maybe others, are probably due to the Power-Save Polling used by the bcm4329 wifi driver; this is described in https://code.google.com/p/cyanogenmod/issues/detail?id=2403 but the fix isn't integrated in CM yet.)

The phone is behind a NAT router but the router doesn't seem to be causing trouble; other softphones have no problem staying registered over the same WLAN.  And this is all while sitting a few feet from the router.

Outbound calls work fine, and inbound calls also work fine when registered.  But the registration frequently drops and re-establishes.  It's not predictable, i.e. doesn't happen at a fixed time interval; sometimes it stays up for several minutes, other times it resets more often.  It happens in both sleep and wake modes.

I think callcentric uses a quite short registration timeout (e.g. 60 seconds) so I'm wondering if the problem is caused by UDP packets in either direction getting lost somehow.  (Registration Timeout is set to 1800 seconds on the phone, but I don't think the server actually uses this.)  But I even see the registration flapping while on calls, with the two-way audio working fine.

[Anonymous]

Originally posted by: fander...@gmail.com

I turned the log level up to 5 and have found a pattern that seems to correspond with the registration problems.  In the following log snippets, EXT_IP is the real external NAT IP address.

It appears that registration requests/replies will ping-pong normally for some time.  Then an event like this will occur:

12-03 16:02:31.268 I/libpjsip(  310):  16:02:31.269    pjsua_acc.c  IP address change detected for account 0 (EXT_IP:50896 --> EXT_IP:51622). Updating registration (using method 2)

After this happens, subsequent registration requests get no replies and are retransmitted several times:

12-03 16:02:59.309 V/libpjsip(  310):  16:02:59.313    tsx0x48e62c  Retransmit timer event
12-03 16:02:59.309 V/libpjsip(  310):  16:02:59.314    tsx0x48e62c  Retransmiting Request msg REGISTER/cseq=52140 (tdta0x495c78), count=8, restart?=1

Finally, a registration failure is returned from the server with code 500 (Network Error):

12-03 16:03:02.948 V/libpjsip(  310):  16:03:02.950 sip_endpoint.c  Processing incoming message: Response msg 500/REGISTER/cseq=52140 (rdata0x480474)
12-03 16:03:02.948 D/libpjsip(  310):  16:03:02.950   pjsua_core.c  RX 306 bytes Response msg 500/REGISTER/cseq=52140 (rdata0x480474) from UDP 204.11.192.34:5080:
12-03 16:03:02.948 D/libpjsip(  310): SIP/2.0 500 Network Failure
  ...
12-03 16:03:02.948 W/libpjsip(  310):  16:03:02.951    pjsua_acc.c  SIP registration failed, status=500 (Network Failure)

So it looks like what's happening is the local port number is changing, and when cSipSimple switches to the new number, it confuses the server and after about 30 seconds a failure notice is sent to the new port and the registration is re-initialized.

But why the local port number would change periodically I have no idea.  Is that something cSipSimple is doing?

[Anonymous]

Originally posted by: fander...@gmail.com

Scratch the last question, I now understand how SIP rport works.  ;)  I don't see why the rport mechanism is failing, but a workaround may be to try to prevent the port changes on the NAT router...

[Anonymous]

Originally posted by: r3gis...@gmail.com

> are probably due to the Power-Save Polling .

Indeed, in latest dev version,"Stay Awake While On Call" is automatically activated for all (with exceptions) HTC devices (previously was only N1, Evo and Desire).

>  It's not predictable, i.e. doesn't happen at a fixed time interval; sometimes it stays up for several minutes, other times it resets more often.  It happens in both sleep and wake modes.

You should try to transform your account into an Expert account (menu > choose wizard).
Here you'll be able to choose keep awake interval for the account and registration time that may help.
You should also try to use the latest version.
As for re-registration, maybe callcentric doesn't support fully the RFC and doesn't like the way pjsip re-register. If so you could try in expert account settings to choose re-writting contact method : legacy. You could also try to disable "rewrite contact field".

Let me know how it goes with these settings. If some helps, I'll integrate it back in the callcentric wizard as default params.

[Anonymous]

Originally posted by: fander...@gmail.com

Thanks r3gis,

When I posted this report I had already been using Expert mode and had tried various values for the Registration Timeout and Keepalive settings and none made any real difference.  (Callcentric always replies with a registration timeout between 60-65 seconds.)

But I found a problem on the NAT router that was causing it to time out UDP state after 1 second, and after fixing this, the problem described above that was resulting in the 500 Network Failure effects seems to have been resolved.  Hpwever, there is still a remaining timeout problem which is causing registration instability.

The logs show the pattern for this second problem.  The code is hitting the failure path from the sent-by check enabled by PJSIP_CHECK_VIA_SENT_BY as described at <http://www.pjsip.org/pjsip/docs/html/groupPJSIPCONFIG.htm> and <http://trac.pjsip.org/repos/ticket/352>.

------------------------------------
12-03 18:57:08.578 D/libpjsip(  310):  18:57:08.585   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54993 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:57:08.578 D/libpjsip(  310): REGISTER sip:callcentric.com SIP/2.0
12-03 18:57:08.578 D/libpjsip(  310): Via: SIP/2.0/UDP INT_IP:5060;rport;branch=z9hG4bKPjHE-r85UIs0WjGfimtZIZOXDbWI.iCfgI
...
12-03 18:57:08.578 D/libpjsip(  310): --end msg--
12-03 18:57:09.459 D/libpjsip(  310):  18:57:09.465   pjsua_core.c  RX 342 bytes Response msg 200/REGISTER/cseq=54993 (rdata0x4c69ec) from UDP 204.11.192.35:5080:
12-03 18:57:09.466 I/libpjsip(  310):  18:57:09.467    pjsua_acc.c  <sip:xxx@callcentric.com>: registration success, status=200 (Ok), will re-register in 61 seconds

...so far so good...

12-03 18:58:05.968 D/libpjsip(  310):  18:58:05.969   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54994 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:58:06.606 D/libpjsip(  310):  18:58:06.608   pjsua_core.c  RX 342 bytes Response msg 200/REGISTER/cseq=54994 (rdata0x4c69ec) from UDP 204.11.192.35:5080:
12-03 18:58:06.606 I/libpjsip(  310):  18:58:06.609    pjsua_acc.c  <sip:xxx@callcentric.com>: registration success, status=200 (Ok), will re-register in 62 seconds

... still good ...

12-03 18:59:04.106 D/libpjsip(  310):  18:59:04.112   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:04.969 D/libpjsip(  310):  18:59:04.975 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:04.976 D/libpjsip(  310):  18:59:04.978 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:05.112 D/libpjsip(  310):  18:59:05.113   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:05.890 D/libpjsip(  310):  18:59:05.895 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:07.107 D/libpjsip(  310):  18:59:07.113   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:08.046 D/libpjsip(  310):  18:59:08.046 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:11.106 D/libpjsip(  310):  18:59:11.113   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:12.036 D/libpjsip(  310):  18:59:12.040 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:15.109 D/libpjsip(  310):  18:59:15.114   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:16.029 D/libpjsip(  310):  18:59:16.033 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:19.113 D/libpjsip(  310):  18:59:19.115   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:20.016 D/libpjsip(  310):  18:59:20.025 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:23.116 D/libpjsip(  310):  18:59:23.116   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:24.016 D/libpjsip(  310):  18:59:24.020 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:27.110 D/libpjsip(  310):  18:59:27.116   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:28.010 D/libpjsip(  310):  18:59:28.014 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:31.116 D/libpjsip(  310):  18:59:31.116   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:32.316 D/libpjsip(  310):  18:59:32.318 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:35.116 D/libpjsip(  310):  18:59:35.117   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=54995 (tdta0x4c8d80) to UDP 204.11.192.35:5080:
12-03 18:59:35.612 W/libpjsip(  310):  18:59:35.612    pjsua_acc.c  SIP registration failed, status=408 (Request Timeout)
12-03 18:59:35.612 D/SIP UA Receiver(  310): New reg state for : 0
12-03 18:59:35.612 D/SIP UA Receiver(  310): In reg state
12-03 18:59:35.626 D/libpjsip(  310):  18:59:35.632   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=64261 (tdta0x2faab0) to UDP 204.11.192.35:5080:
12-03 18:59:35.626 I/libpjsip(  310):  18:59:35.634    pjsua_acc.c  Registration sent
12-03 18:59:36.531 D/libpjsip(  310):  18:59:36.535 sip_endpoint.c  Dropping response Response msg 200/REGISTER/cseq=54995 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:36.531 D/libpjsip(  310):  18:59:36.536 sip_endpoint.c  Dropping response Response msg 407/REGISTER/cseq=64261 (rdata0x4552c4) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:37.401 D/libpjsip(  310):  18:59:37.402 sip_endpoint.c  Dropping response Response msg 407/REGISTER/cseq=64261 (rdata0x4c69ec) from 204.11.192.35:5080 because sent-by is mismatch
12-03 18:59:37.525 D/libpjsip(  310):  18:59:37.531   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=64261 (tdta0x2faab0) to UDP 204.11.192.35:5080:
12-03 18:59:38.321 D/libpjsip(  310):  18:59:38.325 sip_endpoint.c  Dropping response Response msg 407/REGISTER/cseq=64261 (rdata0x4552c4) from 204.11.192.35:5080 because sent-by is mismatch
12-03 19:02:54.713 D/libpjsip(  310):  19:02:54.716   pjsua_core.c  TX 561 bytes Request msg REGISTER/cseq=64261 (tdta0x2faab0) to UDP 204.11.192.35:5080:
12-03 19:02:54.723 W/libpjsip(  310):  19:02:54.723    pjsua_acc.c  SIP registration failed, status=408 (Request Timeout)
12-03 19:02:54.723 D/SIP UA Receiver(  310): New reg state for : 0
12-03 19:02:54.723 D/SIP UA Receiver(  310): In reg state
...
12-03 19:05:30.675 D/libpjsip(  310):  19:05:30.676   pjsua_core.c  TX 560 bytes Request msg REGISTER/cseq=8832 (tdta0x4c8d80) to UDP 204.11.192.23:5080:
12-03 19:05:30.795 D/libpjsip(  310):  19:05:30.802   pjsua_core.c  RX 479 bytes Response msg 407/REGISTER/cseq=8832 (rdata0x4552c4) from UDP 204.11.192.23:5080:
12-03 19:05:30.795 D/libpjsip(  310): SIP/2.0 407 Proxy Authentication Required
12-03 19:05:30.795 D/libpjsip(  310):  19:05:30.803   pjsua_core.c  TX 766 bytes Request msg REGISTER/cseq=8833 (tdta0x4c8d80) to UDP 204.11.192.23:5080:
12-03 19:05:30.955 D/libpjsip(  310):  19:05:30.957   pjsua_core.c  RX 341 bytes Response msg 200/REGISTER/cseq=8833 (rdata0x4552c4) from UDP 204.11.192.23:5080:
12-03 19:05:30.955 D/libpjsip(  310): SIP/2.0 200 Ok
12-03 19:05:30.955 I/libpjsip(  310):  19:05:30.957    pjsua_acc.c  <sip:xxx@callcentric.com>: registration success, status=200 (Ok), will re-register in 60 seconds
------------------------------------

[Anonymous]

Originally posted by: r3gis...@gmail.com

Ok, I could try to disable the flag in pjsip build.

Seems to have not a lot of impact.

I'll turn of the setting in next build and see if there is regression (or if somebody cry about that ;) ).

Summary: Set PJSIP_CHECK_VIA_SENT_BY to 0
Owner: r3gis.3R
Status: Accepted

[Anonymous]

Originally posted by: fander...@gmail.com

Thanks!  Will give it a try as soon as it's available.  Is it in the 0.00-15-18 build?

[Anonymous]

Originally posted by: r3gis...@gmail.com

Indeed, included in 0.00-15-18

Let me know how it goes with the modification.

Status: Started

[Anonymous]

Originally posted by: fander...@gmail.com

With this change registration seems to have become stable at last.  Thanks a lot for the quick fix!

[I did run into a couple of unrelated and minor problems with this build which you might already be aware of.  One is that when setting up the account in the expert wizard, if some values are entered with the wrong syntax so that they appear as orange and the Save button at the bottom is greyed out, if you then hit Menu you get another Save button and if you press it, the application locks up and has to be force-closed.  The other is that with audible dial feedback enabled and vibrate dial feedback disabled, both audible and vibrate feedback occur.  But otherwise the build has been working fine so far.]

[Anonymous]

Originally posted by: r3gis...@gmail.com

Ok for the save in menu will be fixed in next release.
For vibrate & audible feedback that's more tricky.

There is something I did in hurry that is not really clean : if vibrate or tone feedback is set to false in settings it get the setting from the android system.
The actual setting label should be "Force vibrate feedback" and "Force dialtone feedback". Else it fallback to android settings settings. But I've not decided yet if should be a "Auto/Force yes/Force no" list or just a "Force  no" checkbox (or no option at all even if it's needed for workaround some bad device behavior).

Status: NextRelease