search

sonuarya / csipsimple

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

DO NOT restart sip stack immediately if rfc 5626 supported by server #2638

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Activate a sip account
2. Turn off wifi/3g
3. Turn on wifi/3g

What is the expected output? What do you see instead?
Csipsimple should get registered as fast as possible.
But it takes a msm8960 processor 11 seconds to finish registration.

What version of the product are you using? On what device / operating
system?
Nightly, Samsung Galaxy Victory, Android 4.1.2.

Please provide any additional information below.

It looks to be a design choice that Csipsimple restarts the sip stack upon 
network connected(Line 253, DynamicReceiver4.java). However, I would argue that 
this is not a very good choice in term of user experience: users hope to get 
connected as soon as possible.

For example, I have a tasker profile enabling wifi upon incoming call from 
google voice(which rings my cellphone and voip account simultaneously). My goal 
is to get sipsorcery registered asap so I can answer the voip call before the 
other party hangup or get diverted into voicemail. 11 seconds of starting 
csipsimple is just unacceptable for this case.

Maybe we do not really need to fully restart the whole stack, instead we can 
try to reuse a existing stack as much as possible. We can also choose to 
restart the stack at another time, say when network become disconnected.

When the network becoming connected, there are a lot of stuff going on in the 
android system other than csipsimple. Maybe we can even try some trick to 
increase our thread priority temporarily to get registered asap.

Original issue reported on code.google.com by phtr...@gmail.com on 5 Feb 2014 at 10:38

GoogleCodeExporter commented 9 years ago 
Below is my log file for your reference:

02-05 03:10:13.759 D/ConnectivityService(  745): ConnectivityChange for WIFI: 
CONNECTED/CONNECTED
02-05 03:10:14.450 D/DynamicReceiver( 9982): Internal receive 
android.net.conn.CONNECTIVITY_CHANGE
02-05 03:10:14.480 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:14.490 D/DynamicReceiver( 9982): onConnectivityChanged(): null -> 
WIFI
02-05 03:10:14.490 D/SIP SRV ( 9982): Stop sip stack
02-05 03:10:14.490 D/PjService( 9982): >> SIP STOP <<
02-05 03:10:14.500 D/PjService( 9982): Detroying...
02-05 03:10:14.510 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:14.510 D/libpjsip( 9982): 03:10:14.518   pjsua_core.c !Shutting 
down, flags=0...
02-05 03:10:14.510 D/libpjsip( 9982): 03:10:14.518   pjsua_core.c  PJSUA state 
changed: RUNNING --> CLOSING
02-05 03:10:14.510 D/libpjsip( 9982): 03:10:14.524   pjsua_call.c  .Hangup all 
calls..
02-05 03:10:14.510 D/libpjsip( 9982): 03:10:14.524   pjsua_pres.c  .Shutting 
down presence..
02-05 03:10:14.510 D/libpjsip( 9982): 03:10:14.526  pjsua_media.c  .Shutting 
down media..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814  pjsua_media.c  ..Call 0: 
deinitializing media..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814  pjsua_media.c  ..Call 1: 
deinitializing media..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814  pjsua_media.c  ..Call 2: 
deinitializing media..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814  pjsua_media.c  ..Call 3: 
deinitializing media..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ..Destroying 
video subsystem..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 0: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 1: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 2: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 3: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 4: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.814    pjsua_vid.c  ...Window 5: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 6: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 7: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 8: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 9: 
destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
10: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
11: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
12: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
13: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
14: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815    pjsua_vid.c  ...Window 
15: destroying..
02-05 03:10:14.801 D/libpjsip( 9982): 03:10:14.815   opensl_dev.c  ..OpenSL 
sound library shutting down..
02-05 03:10:15.571 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:15.581 D/Device State( 9982): Try to start service if not already 
started
02-05 03:10:15.641 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:15.641 D/SIP SRV ( 9982): Direct sip start
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823   pjsua_core.c  
.Destroying...
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_transactio  .Stopping 
transaction layer module
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_transactio  .Stopped 
transaction layer module
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-unsolicited-mwi" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-pjsua-options" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-pjsua-im" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-pjsua-pres" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-pjsua" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-stateful-util" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-refer" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.823 sip_endpoint.c  .Module 
"mod-mwi" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-presence" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-evsub" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-invite" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-100rel" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-ua" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_transactio  .Transaction 
layer module destroyed
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-tsx-layer" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-reg-tracker" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-earlylock" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-opus-sdp-rewriter" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-msg-print" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.824 sip_endpoint.c  .Module 
"mod-pjsua-log" unregistered
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.825   tcplis:34396  .SIP TCP 
listener destroyed
02-05 03:10:15.812 D/libpjsip( 9982): 03:10:15.825   tlslis:45075  .SIP TLS 
listener destroyed
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.827 sip_endpoint.c  .Endpoint 
0x40f53c3c destroyed
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.827    stunresolve  .Pool is not 
released by application, releasing now
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.827 glck0x5bf48d40  .Pool is not 
released by application, releasing now
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.827    stunresolve  .Pool is not 
released by application, releasing now
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.827    stunresolve  .Pool is not 
released by application, releasing now
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.828   pjsua_core.c  .PJSUA state 
changed: CLOSING --> NULL
02-05 03:10:15.822 D/libpjsip( 9982): 03:10:15.828   pjsua_core.c  .PJSUA 
destroyed...
02-05 03:10:15.822 I/MediaManager( 9982): Remove media manager....
02-05 03:10:15.822 D/BT8     ( 9982): Unregister BT media receiver
02-05 03:10:15.832 D/SIP SRV ( 9982): Accounts status.onChange( false)
02-05 03:10:15.832 D/SIP SRV ( 9982): Update registration state
02-05 03:10:15.832 D/SIP SRV ( 9982): Stop and unregister device receiver
02-05 03:10:15.842 D/SIP SRV ( 9982): Unregister telephony receiver
02-05 03:10:15.852 D/dalvikvm( 9982): WAIT_FOR_CONCURRENT_GC blocked 0ms
02-05 03:10:15.912 D/dalvikvm( 9982): GC_EXPLICIT freed 645K, 47% free 
10484K/19523K, paused 7ms+12ms, total 63ms
02-05 03:10:16.012 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:16.012 D/SIP SRV ( 9982): Start was asked and we should actually 
start now
02-05 03:10:16.012 D/SIP SRV ( 9982): Ask pjservice to start itself
02-05 03:10:16.022 D/PjService( 9982): Starting sip stack
02-05 03:10:16.973 I/PjService( 9982): Created 0
02-05 03:10:16.973 D/PjService( 9982): create ua receiver
02-05 03:10:16.973 D/SIP UA Receiver( 9982): Create async worker !!!
02-05 03:10:17.013 D/BT8     ( 9982): Register BT media receiver
02-05 03:10:17.013 D/BT8     ( 9982): >>> BT SCO state changed !!! 
02-05 03:10:17.013 D/BT8     ( 9982): BT SCO state changed : 0 target is false
02-05 03:10:17.073 D/PjService( 9982): Attach is done to callback
02-05 03:10:17.183 D/PjService( 9982): Use OpenSL-ES implementation
02-05 03:10:17.253 D/PjService( 9982): add server 
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.398 sip_endpoint.c  .Module 
"mod-pjsua-log" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.398 sip_endpoint.c  .Module 
"mod-tsx-layer" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.398 sip_endpoint.c  .Module 
"mod-stateful-util" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.399 sip_endpoint.c  .Module 
"mod-ua" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.399 sip_endpoint.c  .Module 
"mod-100rel" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.399 sip_endpoint.c  .Module 
"mod-pjsua" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.399 sip_endpoint.c  .Module 
"mod-invite" registered
02-05 03:10:17.393 D/libpjsip( 9982): 03:10:17.399   pjsua_core.c  .Trying STUN 
server  (1 of 1)..
02-05 03:10:18.485 D/libpjsip( 9982): 03:10:18.493   pjsua_core.c  .Error 
starting STUN socket for : gethostbyname() has returned error (PJ_ERESOLVE)
02-05 03:10:18.485 E/libpjsip( 9982): 03:10:18.493   pjsua_core.c  .STUN 
resolution failed: gethostbyname() has returned error (PJ_ERESOLVE)
02-05 03:10:18.485 W/libpjsip( 9982): 03:10:18.493   pjsua_core.c  .Ignoring 
STUN resolution failure (by setting)
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.501          pjlib  ..select() 
I/O Queue created (0x5c124e64)
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.501 webrtc_codec.c  ..List of 
supported codec.
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.502 webrtc_codec.c  ..0 ISAC 103 
16000 480 32000
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.502 webrtc_codec.c  ..5 ILBC 102 
8000 240 13300
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.502         silk.c  ..SILK codec 
version 1.0.9 initialized
02-05 03:10:18.495 D/libpjsip( 9982): 03:10:18.502 sip_endpoint.c  ..Module 
"mod-opus-sdp-rewriter" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.508    pjsua_vid.c  
..Initializing video subsystem..
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.508 sip_endpoint.c  .Module 
"mod-evsub" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.508 sip_endpoint.c  .Module 
"mod-presence" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.509 sip_endpoint.c  .Module 
"mod-mwi" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.509 sip_endpoint.c  .Module 
"mod-refer" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.509 sip_endpoint.c  .Module 
"mod-pjsua-pres" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.509 sip_endpoint.c  .Module 
"mod-pjsua-im" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.509 sip_endpoint.c  .Module 
"mod-pjsua-options" registered
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.510   pjsua_core.c  .1 SIP 
worker threads created
02-05 03:10:18.505 I/libpjsip( 9982): 03:10:18.510   pjsua_core.c  .pjsua 
version 2.1-svn for  initialized
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.510   pjsua_core.c  .PJSUA state 
changed: CREATED --> INIT
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.510   opensl_dev.c  OpenSL sound 
library initialized
02-05 03:10:18.505 D/libpjsip( 9982): 03:10:18.510 pjsua_jni_addo  Loaded audio 
dev
02-05 03:10:19.476 D/libpjsip( 9982): 03:10:19.480   pjsua_core.c  SIP UDP 
socket reachable at 192.168.1.3:38128
02-05 03:10:19.476 D/libpjsip( 9982): 03:10:19.480  udp0x5c02b678  SIP UDP 
transport started, published address is 192.168.1.3:38128
02-05 03:10:19.476 D/libpjsip( 9982): 03:10:19.480    pjsua_acc.c  Adding 
account: id=<sip:192.168.1.3:38128>
02-05 03:10:19.476 D/libpjsip( 9982): 03:10:19.480    pjsua_acc.c  .Account 
<sip:192.168.1.3:38128> added with id 0
02-05 03:10:19.546 D/dalvikvm( 9982): WAIT_FOR_CONCURRENT_GC blocked 0ms
02-05 03:10:19.586 D/dalvikvm( 9982): GC_EXPLICIT freed 349K, 47% free 
10453K/19523K, paused 3ms+4ms, total 38ms
02-05 03:10:20.437 D/libpjsip( 9982): 03:10:20.446   tcplis:54420  SIP TCP 
listener ready for incoming connections at 192.168.1.3:54420
02-05 03:10:20.437 D/libpjsip( 9982): 03:10:20.446    pjsua_acc.c  Adding 
account: id=<sip:192.168.1.3:54420;transport=TCP>
02-05 03:10:20.437 D/libpjsip( 9982): 03:10:20.446    pjsua_acc.c  .Account 
<sip:192.168.1.3:54420;transport=TCP> added with id 1
02-05 03:10:21.428 D/libpjsip( 9982): 03:10:21.446   tlslis:57426  SIP TLS 
listener is ready for incoming connections at 192.168.1.3:57426
02-05 03:10:21.428 D/libpjsip( 9982): 03:10:21.446    pjsua_acc.c  Adding 
account: id=<sip:192.168.1.3:57426;transport=TLS>
02-05 03:10:21.428 D/libpjsip( 9982): 03:10:21.446    pjsua_acc.c  .Account 
<sip:192.168.1.3:57426;transport=TLS> added with id 2
02-05 03:10:21.438 D/libpjsip( 9982): 03:10:21.452 sip_endpoint.c  Module 
"mod-earlylock" registered
02-05 03:10:21.438 D/libpjsip( 9982): 03:10:21.452 sip_endpoint.c  Module 
"mod-reg-tracker" registered
02-05 03:10:21.438 D/RegHandlerModule( 9982): Reg handler module added with 
status 0
02-05 03:10:21.438 D/libpjsip( 9982): 03:10:21.452   pjsua_core.c  PJSUA state 
changed: INIT --> STARTING
02-05 03:10:21.438 E/libpjsip( 9982): 03:10:21.452  pjsua_media.c  ..NAT type 
detection failed: Invalid STUN server or server not configured 
(PJNATH_ESTUNINSERVER)
02-05 03:10:21.448 D/libpjsip( 9982): 03:10:21.457 sip_endpoint.c  .Module 
"mod-unsolicited-mwi" registered
02-05 03:10:21.448 D/libpjsip( 9982): 03:10:21.458   pjsua_core.c  .PJSUA state 
changed: STARTING --> RUNNING
02-05 03:10:21.898 D/PjService( 9982): Audio codecs : PCMU/8000/1 (60) - 
PCMA/8000/1 (50) - ISAC/16000/1 (1) - SILK/24000/1 (220) - opus/16000/1 (1) - 
02-05 03:10:21.898 D/PjService( 9982): Video codecs : 
02-05 03:10:21.938 D/DynamicReceiver( 9982): Start monitoring of route file ? 0
02-05 03:10:21.938 D/SIP SRV ( 9982): Listen for phone state 
02-05 03:10:21.958 D/SIP SRV ( 9982): Add all accounts
02-05 03:10:21.958 D/SIP SRV ( 9982): We are adding all accounts right now....
02-05 03:10:22.008 D/PjSipAccount( 9982): Create proxy 0
02-05 03:10:22.058 D/libpjsip( 9982): 03:10:22.071    pjsua_acc.c  Adding 
account: id=<sip:xxxx@sipsorcery.com>
02-05 03:10:22.058 D/libpjsip( 9982): 03:10:22.071    pjsua_acc.c  .Account 
<sip:xxxx@sipsorcery.com> added with id 3
02-05 03:10:22.058 D/libpjsip( 9982): 03:10:22.072    pjsua_acc.c  Acc 3: 
setting registration..
02-05 03:10:23.109 D/libpjsip( 9982): 03:10:23.124 tcpc0x5c045f4c  ..TCP client 
transport created
02-05 03:10:23.109 D/libpjsip( 9982): 03:10:23.124 tcpc0x5c045f4c  ..TCP 
transport 192.168.1.3:58241 is connecting to 67.222.131.147:2060...
02-05 03:10:23.109 D/libpjsip( 9982): 03:10:23.124   pjsua_core.c  ..TX 537 
bytes Request msg REGISTER/cseq=32679 (tdta0x5c0446a8) to TCP 
67.222.131.147:2060:
02-05 03:10:23.109 D/libpjsip( 9982): REGISTER 
sip:sipsorcery.com:2060;transport=tcp;lr SIP/2.0

02-05 03:10:23.109 D/libpjsip( 9982): v: SIP/2.0/TCP 
192.168.1.3:58241;rport;branch=z9hG4bKPjXZW8dsaSUk84drjZCJsG2sKETIAcv2oU;alias

02-05 03:10:23.109 D/libpjsip( 9982): Max-Forwards: 70

02-05 03:10:23.109 D/libpjsip( 9982): f: 
<sip:xxxx@sipsorcery.com>;tag=O1K6AquYjHh8JF.cTazHrIk-JbBhoQGk

02-05 03:10:23.109 D/libpjsip( 9982): t: <sip:xxxx@sipsorcery.com>

02-05 03:10:23.109 D/libpjsip( 9982): i: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:23.109 D/libpjsip( 9982): CSeq: 32679 REGISTER

02-05 03:10:23.109 D/libpjsip( 9982): User-Agent: CSipSimple.G729

02-05 03:10:23.109 D/libpjsip( 9982): m: 
<sip:xxxx@192.168.1.3:54420;transport=TCP>;+sip.ice

02-05 03:10:23.109 D/libpjsip( 9982): Expires: 900

02-05 03:10:23.109 D/libpjsip( 9982): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS

02-05 03:10:23.109 D/libpjsip( 9982): l:  0

02-05 03:10:23.109 D/libpjsip( 9982): 

02-05 03:10:23.109 D/libpjsip( 9982): --end msg--
02-05 03:10:23.119 D/libpjsip( 9982): 03:10:23.128    pjsua_acc.c  .Acc 3: 
Registration sent
02-05 03:10:23.119 D/DBProvider( 9982): Added status_text= status_code=-1 
display_name=SIPSorcery expires=0 account_id=4 added_status=0 priority=0 
active=true wizard=EXPERT reg_uri=sip:sipsorcery.com:2060 pjsua_id=3
02-05 03:10:23.119 D/libpjsip( 9982): 03:10:23.135    pjsua_acc.c  Acc 3: 
setting online status to 1..
02-05 03:10:23.129 D/SIP SRV ( 9982): Accounts status.onChange( false)
02-05 03:10:23.129 D/SIP SRV ( 9982): Update registration state
02-05 03:10:23.190 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:23.190 D/SIP SRV ( 9982): Start was asked and we should actually 
start now
02-05 03:10:23.190 D/SIP SRV ( 9982): Ask pjservice to start itself
02-05 03:10:23.190 D/dalvikvm( 9982): WAIT_FOR_CONCURRENT_GC blocked 0ms
02-05 03:10:23.190 D/libpjsip( 9982): 03:10:23.204 tcpc0x5c045f4c !TCP 
transport 192.168.1.3:58241 is connected to 67.222.131.147:2060
02-05 03:10:23.230 D/dalvikvm( 9982): GC_EXPLICIT freed 414K, 47% free 
10478K/19523K, paused 3ms+6ms, total 45ms
02-05 03:10:23.250 D/DynamicReceiver( 9982): Internal receive 
android.net.conn.CONNECTIVITY_CHANGE
02-05 03:10:23.260 D/libpjsip( 9982): 03:10:23.273   pjsua_core.c  .RX 502 
bytes Response msg 401/REGISTER/cseq=32679 (rdata0x5c0460fc) from TCP 
67.222.131.147:2060:
02-05 03:10:23.260 D/libpjsip( 9982): SIP/2.0 401 Unauthorised

02-05 03:10:23.260 D/libpjsip( 9982): Via: SIP/2.0/TCP 
192.168.1.3:58241;rport=58241;branch=z9hG4bKPjXZW8dsaSUk84drjZCJsG2sKETIAcv2oU;a
lias;received=67.173.9.164

02-05 03:10:23.260 D/libpjsip( 9982): To: <sip:xxxx@sipsorcery.com>

02-05 03:10:23.260 D/libpjsip( 9982): From: 
<sip:xxxx@sipsorcery.com>;tag=O1K6AquYjHh8JF.cTazHrIk-JbBhoQGk

02-05 03:10:23.260 D/libpjsip( 9982): Call-ID: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:23.260 D/libpjsip( 9982): CSeq: 32679 REGISTER

02-05 03:10:23.260 D/libpjsip( 9982): WWW-Authenticate: Digest 
realm="sipsorcery.com",nonce="16432337902066415797"

02-05 03:10:23.260 D/libpjsip( 9982): Content-Length: 0

02-05 03:10:23.260 D/libpjsip( 9982): Allow: ACK, BYE, CANCEL, INFO, INVITE, 
NOTIFY, OPTIONS, REFER, REGISTER, SUBSCRIBE

02-05 03:10:23.260 D/libpjsip( 9982): 

02-05 03:10:23.260 D/libpjsip( 9982): --end msg--
02-05 03:10:23.260 D/libpjsip( 9982): 03:10:23.274 mobile_reg_han  
.mod_reg_tracker_on_rx_response
02-05 03:10:23.260 D/libpjsip( 9982): 03:10:23.274 mobile_reg_han  
.mod_reg_tracker_on_rx_response done
02-05 03:10:23.270 D/PjService( 9982): Found pjsua 3 searching 3
02-05 03:10:23.270 D/RegHandlerReceiver( 9982): We restore 
<sip:xxxx@67.173.9.164:60671;transport=TCP>;+sip.ice
02-05 03:10:23.270 D/libpjsip( 9982): 03:10:23.283 mobile_reg_han  ....Hook a 
RX request
02-05 03:10:23.270 D/libpjsip( 9982): 03:10:23.283   pjsua_core.c  ....TX 792 
bytes Request msg REGISTER/cseq=32680 (tdta0x5c0446a8) to TCP 
67.222.131.147:2060:
02-05 03:10:23.270 D/libpjsip( 9982): REGISTER 
sip:sipsorcery.com:2060;transport=tcp;lr SIP/2.0

02-05 03:10:23.270 D/libpjsip( 9982): v: SIP/2.0/TCP 
192.168.1.3:58241;rport;branch=z9hG4bKPjyUfdWsmEPgoAg1fmBW-2.Piks3OqgjQf;alias

02-05 03:10:23.270 D/libpjsip( 9982): Max-Forwards: 70

02-05 03:10:23.270 D/libpjsip( 9982): f: 
<sip:xxxx@sipsorcery.com>;tag=O1K6AquYjHh8JF.cTazHrIk-JbBhoQGk

02-05 03:10:23.270 D/libpjsip( 9982): t: <sip:xxxx@sipsorcery.com>

02-05 03:10:23.270 D/libpjsip( 9982): i: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:23.270 D/libpjsip( 9982): CSeq: 32680 REGISTER

02-05 03:10:23.270 D/libpjsip( 9982): User-Agent: CSipSimple.G729

02-05 03:10:23.270 D/libpjsip( 9982): m: 
<sip:xxxx@192.168.1.3:54420;transport=TCP>;+sip.ice

02-05 03:10:23.270 D/libpjsip( 9982): Expires: 900

02-05 03:10:23.270 D/libpjsip( 9982): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS

02-05 03:10:23.270 D/libpjsip( 9982): Authorization: Digest username="xxxx", 
realm="sipsorcery.com", nonce="16432337902066415797", 
uri="sip:sipsorcery.com:2060;transport=tcp;lr", 
response="5de29825d85d4755b534bac36a945403"

02-05 03:10:23.270 D/libpjsip( 9982): m: 
<sip:xxxx@67.173.9.164:60671;transport=TCP>;expires=0;+sip.ice

02-05 03:10:23.280 D/libpjsip( 9982): l:  0

02-05 03:10:23.280 D/libpjsip( 9982): 

02-05 03:10:23.280 D/libpjsip( 9982): --end msg--
02-05 03:10:23.290 D/Prefs   ( 9982): We are valid for WIFI
02-05 03:10:23.290 D/DynamicReceiver( 9982): onConnectivityChanged(): null -> 
WIFI
02-05 03:10:23.460 D/libpjsip( 9982): 03:10:23.469   pjsua_core.c  .RX 476 
bytes Response msg 200/REGISTER/cseq=32680 (rdata0x5c0460fc) from TCP 
67.222.131.147:2060:
02-05 03:10:23.460 D/libpjsip( 9982): SIP/2.0 200 Ok

02-05 03:10:23.460 D/libpjsip( 9982): Via: SIP/2.0/TCP 
192.168.1.3:58241;rport=58241;branch=z9hG4bKPjyUfdWsmEPgoAg1fmBW-2.Piks3OqgjQf;a
lias;received=67.173.9.164

02-05 03:10:23.460 D/libpjsip( 9982): To: 
<sip:xxxx@sipsorcery.com>;tag=SGTRMDEVXE

02-05 03:10:23.460 D/libpjsip( 9982): From: 
<sip:xxxx@sipsorcery.com>;tag=O1K6AquYjHh8JF.cTazHrIk-JbBhoQGk

02-05 03:10:23.460 D/libpjsip( 9982): Call-ID: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:23.460 D/libpjsip( 9982): CSeq: 32680 REGISTER

02-05 03:10:23.460 D/libpjsip( 9982): Contact: 
<sip:xxxx@192.168.1.3:54420;transport=TCP>;expires=900

02-05 03:10:23.460 D/libpjsip( 9982): Date: Wed, 05 Feb 2014 09:10:24 GMT

02-05 03:10:23.460 D/libpjsip( 9982): Content-Length: 0

02-05 03:10:23.460 D/libpjsip( 9982): Server: www.sipsorcery.com

02-05 03:10:23.460 D/libpjsip( 9982): 

02-05 03:10:23.460 D/libpjsip( 9982): --end msg--
02-05 03:10:23.460 D/libpjsip( 9982): 03:10:23.469 mobile_reg_han  
.mod_reg_tracker_on_rx_response
02-05 03:10:23.460 D/libpjsip( 9982): 03:10:23.469 mobile_reg_han  
.mod_reg_tracker_on_rx_response 2
02-05 03:10:23.460 D/libpjsip( 9982): 03:10:23.469 mobile_reg_han  .Hook a 
REGISTER RX response !!!
02-05 03:10:23.460 D/libpjsip( 9982): 03:10:23.469 mobile_reg_han  . Hook 
should save contact : <sip:xxxx@192.168.1.3:54420;transport=TCP>;+sip.ice > 900
02-05 03:10:23.660 D/PjService( 9982): Found pjsua 3 searching 3
02-05 03:10:23.680 D/libpjsip( 9982): 03:10:23.691 mobile_reg_han  
.mod_reg_tracker_on_rx_response done
02-05 03:10:23.690 D/libpjsip( 9982): 03:10:23.701    pjsua_acc.c  ....SIP 
outbound status for acc 3 is not active
02-05 03:10:23.690 I/libpjsip( 9982): 03:10:23.701    pjsua_acc.c  ....IP 
address change detected for account 3 (192.168.1.3:54420 --> 
67.173.9.164:58241). Updating registration (using method 2)
02-05 03:10:23.690 D/libpjsip( 9982): 03:10:23.701    pjsua_acc.c  ....Acc 3: 
setting registration..
02-05 03:10:24.571 D/PjService( 9982): Found pjsua 3 searching 3
02-05 03:10:24.571 D/RegHandlerReceiver( 9982): We restore 
<sip:xxxx@192.168.1.3:54420;transport=TCP>;+sip.ice
02-05 03:10:24.571 D/libpjsip( 9982): 03:10:24.581 mobile_reg_han  ......The 
register already has old contact in it, ignore
02-05 03:10:24.571 D/libpjsip( 9982): 03:10:24.581   pjsua_core.c  ......TX 792 
bytes Request msg REGISTER/cseq=32681 (tdta0x5c0493e8) to TCP 
67.222.131.147:2060:
02-05 03:10:24.571 D/libpjsip( 9982): REGISTER 
sip:sipsorcery.com:2060;transport=tcp;lr SIP/2.0

02-05 03:10:24.571 D/libpjsip( 9982): v: SIP/2.0/TCP 
192.168.1.3:58241;rport;branch=z9hG4bKPjyMlCfbKeLIogKi514PsXOdqLex6CxE3X;alias

02-05 03:10:24.571 D/libpjsip( 9982): Max-Forwards: 70

02-05 03:10:24.571 D/libpjsip( 9982): f: 
<sip:xxxx@sipsorcery.com>;tag=wBJN6ReoTlSLeTX1KI0tMJoFI5202guZ

02-05 03:10:24.571 D/libpjsip( 9982): t: <sip:xxxx@sipsorcery.com>

02-05 03:10:24.571 D/libpjsip( 9982): i: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:24.571 D/libpjsip( 9982): CSeq: 32681 REGISTER

02-05 03:10:24.571 D/libpjsip( 9982): Authorization: Digest username="xxxx", 
realm="sipsorcery.com", nonce="16432337902066415797", 
uri="sip:sipsorcery.com:2060;transport=tcp;lr", 
response="5de29825d85d4755b534bac36a945403"

02-05 03:10:24.571 D/libpjsip( 9982): User-Agent: CSipSimple.G729

02-05 03:10:24.571 D/libpjsip( 9982): m: 
<sip:xxxx@67.173.9.164:58241;transport=TCP>;+sip.ice

02-05 03:10:24.571 D/libpjsip( 9982): m: 
<sip:xxxx@192.168.1.3:54420;transport=TCP>;expires=0;+sip.ice

02-05 03:10:24.571 D/libpjsip( 9982): Expires: 900

02-05 03:10:24.571 D/libpjsip( 9982): Allow: PRACK, INVITE, ACK, BYE, CANCEL, 
UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS

02-05 03:10:24.571 D/libpjsip( 9982): l:  0

02-05 03:10:24.571 D/libpjsip( 9982): 

02-05 03:10:24.571 D/libpjsip( 9982): --end msg--
02-05 03:10:24.581 D/libpjsip( 9982): 03:10:24.587    pjsua_acc.c  .....Acc 3: 
Registration sent
02-05 03:10:24.661 D/libpjsip( 9982): 03:10:24.672   pjsua_core.c  .RX 477 
bytes Response msg 200/REGISTER/cseq=32681 (rdata0x5c0460fc) from TCP 
67.222.131.147:2060:
02-05 03:10:24.661 D/libpjsip( 9982): SIP/2.0 200 Ok

02-05 03:10:24.661 D/libpjsip( 9982): Via: SIP/2.0/TCP 
192.168.1.3:58241;rport=58241;branch=z9hG4bKPjyMlCfbKeLIogKi514PsXOdqLex6CxE3X;a
lias;received=67.173.9.164

02-05 03:10:24.661 D/libpjsip( 9982): To: 
<sip:xxxx@sipsorcery.com>;tag=MOACJKMSBG

02-05 03:10:24.661 D/libpjsip( 9982): From: 
<sip:xxxx@sipsorcery.com>;tag=wBJN6ReoTlSLeTX1KI0tMJoFI5202guZ

02-05 03:10:24.661 D/libpjsip( 9982): Call-ID: pWeXxRBdypUZSR6zLWVOxO.x3X2O9rK2

02-05 03:10:24.661 D/libpjsip( 9982): CSeq: 32681 REGISTER

02-05 03:10:24.661 D/libpjsip( 9982): Contact: 
<sip:xxxx@67.173.9.164:58241;transport=TCP>;expires=900

02-05 03:10:24.661 D/libpjsip( 9982): Date: Wed, 05 Feb 2014 09:10:25 GMT

02-05 03:10:24.661 D/libpjsip( 9982): Content-Length: 0

02-05 03:10:24.661 D/libpjsip( 9982): Server: www.sipsorcery.com

02-05 03:10:24.661 D/libpjsip( 9982): 

02-05 03:10:24.661 D/libpjsip( 9982): --end msg--
02-05 03:10:24.661 D/libpjsip( 9982): 03:10:24.675 mobile_reg_han  
.mod_reg_tracker_on_rx_response
02-05 03:10:24.661 D/libpjsip( 9982): 03:10:24.676 mobile_reg_han  
.mod_reg_tracker_on_rx_response 2
02-05 03:10:24.661 D/libpjsip( 9982): 03:10:24.676 mobile_reg_han  .Hook a 
REGISTER RX response !!!
02-05 03:10:24.661 D/libpjsip( 9982): 03:10:24.676 mobile_reg_han  . Hook 
should save contact : <sip:xxxx@67.173.9.164:58241;transport=TCP>;+sip.ice > 900
02-05 03:10:24.671 D/PjService( 9982): Found pjsua 3 searching 3
02-05 03:10:24.701 D/libpjsip( 9982): 03:10:24.712 mobile_reg_han  
.mod_reg_tracker_on_rx_response done
02-05 03:10:24.711 D/libpjsip( 9982): 03:10:24.726    pjsua_acc.c  ....SIP 
outbound status for acc 3 is not active
02-05 03:10:24.711 I/libpjsip( 9982): 03:10:24.726    pjsua_acc.c  
....<sip:xxxx@sipsorcery.com>: registration success, status=200 (Ok), will 
re-register in 900 seconds
02-05 03:10:24.711 D/SIP UA Receiver( 9982): < LOCK CPU
02-05 03:10:24.721 D/PjService( 9982): Found pjsua 3 searching 3
02-05 03:10:24.731 D/PjService( 9982): Update profile from service for 3 aka in 
db 4
02-05 03:10:24.731 D/SIP UA Receiver( 9982): > UNLOCK CPU 0
02-05 03:10:24.731 D/DBProvider( 9982): Updated status_text=OK status_code=200 
display_name=SIPSorcery expires=894 account_id=4 added_status=0 priority=0 
active=true wizard=EXPERT reg_uri=sip:sipsorcery.com:2060 pjsua_id=3
02-05 03:10:24.741 D/PjService( 9982): Profile state UP : status_text=OK 
status_code=200 expires=894
02-05 03:10:24.771 D/SIP SRV ( 9982): Accounts status.onChange( false)
02-05 03:10:24.771 D/SIP SRV ( 9982): Update registration state

Original comment by phtr...@gmail.com on 5 Feb 2014 at 10:40

GoogleCodeExporter commented 9 years ago 
It's a software design choice. In order to clear all state of the sip stack 
it's choosen to stop and restart totally the stack. It's the shorter way to do 
and is not so bad compared to alternative that are bug prone 
(http://trac.pjsip.org/repos/wiki/IPAddressChange). Also in android it's 
advised to wait a little so that the network layer is fully ready again for 
transport.

BTW, I think that this is the delay you observe, the sip stack restart does not 
take so many time that it should be noticeable. 
If you have a close look to logs, you'll see that it restarts in 7 seconds 
(10:17 to 10:24) and that half of this time is spent trying to bind local 
sockets and resolving network :
17 -> 18 : spent to request stun server... that is unresolvable ! (what is your 
stun config? maybe there is a problem here, or maybe the network layer is not 
yet fully ready)
18 -> 19 : spent to bind udp socket
19 -> 20 : spent to bind tcp socket
20 -> 21 : spetn to bind tls socket => do you need it, maybe you can disable 
this option and save 1 second?
after that time is spend in network communication (and the app receive at 10:23 
a final confirmation of the fact the network layer is fully ready) (
02-05 03:10:23.290 D/DynamicReceiver( 9982): onConnectivityChanged(): null -> 
WIFI)

So, compared to a solution where you have registration changed and all 
interface rebound as listening socket... there is no performance difference at 
all ! If we compare between a precise solution that would only rebind listening 
sockets on new interfaces + send a re-register and a solution that restarts the 
entire stack : the long time spent is time spent to re-bind sockets and to 
re-register. It's not time spent allocating pjsip stack and modules and 
launching them (maybe the only small thing that takes time from your logs is 
the codec allocation, but it's very few time compared to the rest). 

Another point : during the time of the restart you are actually not connected 
to the server, and IMHO it's good to remove the csipsimple icon from 
notification bar during this time.

Original comment by r3gis...@gmail.com on 5 Feb 2014 at 3:50

GoogleCodeExporter commented 9 years ago 
>>the long time spent is time spent to re-bind sockets and to re-register.

Actually, we don't need to bind udp/tcp/tls before making network connection if 
RFC5626 is used. The only necessary spending in this case is from 10:22.058 to 
10:23.460, if I disable the stun server totally.

At least we can schedule the stack-destruction task right after the NetworkOff 
event, without changing the current design structure too much, right?

Original comment by phtr...@gmail.com on 5 Feb 2014 at 5:28

GoogleCodeExporter commented 9 years ago 
 we don't need to bind udp/tcp/tls before making network connection if RFC5626 is used. 

Yep you are right. I didn't thought about this case. Indeed if rfc5626 is 
supported by server with TCP or TLS there's something that could maybe done. It 
would not be very simple implementation however because when android tell app a 
network type is lost it does not tells a new one will come soon. And in case 
none come I would like to keep the current behavior (stack and service stopped 
and consuming no more CPU)
So, I change the issue state to accepted enhancement. It does not go in my 
personal task list however because I personnaly don't see big benefit to that + 
is at risk that some changes has to be made in pjsip layer + have few free time 
for csipsimple those days and free time will be spent on more critical problems 
;). But if anyone contribute a robust solution for this, it will be welcome :)

>> At least we can schedule the stack-destruction task right after the 
NetworkOff event
Mmmh, should be the case. what do you consider to be the "network off" event in 
terms of android SDK? Normally as soon as network changes (lost or change) 
(except if a hidden hacky option of CSipSimple is used or if there is an 
ongoing call) the sip service is stopped (restarted) immediately if I don't 
mistake (but I could have forgot things on this part : it's a stable one that I 
didn't changed for a while)

Original comment by r3gis...@gmail.com on 5 Feb 2014 at 11:01

GoogleCodeExporter commented 9 years ago

Original comment by r3gis...@gmail.com on 22 Jun 2015 at 11:31