#117 sofia-sip rapidly loses connection
I'm using sipgate and it works for a few seconds and then I see multiple bad requests like this (Seems to choke on P-Registrar-Error: Invalid CSeq number)
(telepathy-sofiasip:5855): tpsip-DEBUG: SIP/2.0 400 Bad Request
(telepathy-sofiasip:5855): tpsip-DEBUG: Via: SIP/2.0/UDP 192.168.1.38:409022;received=80.25.47.15;rport=40902;branch=z9hG4bK2cU8p67yBBDaa
(telepathy-sofiasip:5855): tpsip-DEBUG: From: <sip:3456789@sipgate.de>;tag=Z5p75FH8me8He
(telepathy-sofiasip:5855): tpsip-DEBUG: To: <sip:3456789@sipgate.de>;tag=e6312186bd5c2eb4571f6550243cfacc.0682
(telepathy-sofiasip:5855): tpsip-DEBUG: Call-ID: 1da2e23a-4687-122f-64a6-0025647b5e48
(telepathy-sofiasip:5855): tpsip-DEBUG: CSeq: 880728255 REGISTER
(telepathy-sofiasip:5855): tpsip-DEBUG: Contact: <sip:3456789@80.25.47.15:49949>;expires=118, <sip:3456789@80.25.47.15:45516;transport=udp>;expires=353;received="sip:80.25.47.15:45516", <sip:3456789@80.25.47.15:54106>;expires=388, <sip:3456789@80.25.47.15:41581>;expires=429, <sip:3456789@80.25.47.15:41581;transport=udp>;expires=430;received="sip:80.25.47.15:41581", <sip:3456789@80.25.47.15:60425>;expires=509, <sip:3456789@80.25.47.15:47510>;expires=545, <sip:3456789@80.25.47.15:47510;transport=udp>;expires=545;received="sip:80.25.47.15:47510", <sip:3456789@80.25.47.15:48344;transport=udp>;expires=547, <sip:3456789@80.25.47.15:33454>;expires=555, <sip:3456789@80.25.47.15:33454;transport=udp>;expires=556;received="sip:80.25.47.15:33454", <sip:3456789@80.25.47.15:40902>;expires=577, <sip:3456789@80.25.47.15:40902;transport=udp>;expires=577;received="sip:80.25.47.15:40902"
(telepathy-sofiasip:5855): tpsip-DEBUG: P-Registrar-Error: Invalid CSeq number
(telepathy-sofiasip:5855): tpsip-DEBUG: Content-Length: 0
(telepathy-sofiasip:5855): tpsip-DEBUG:
Which seems to trigger a shutdown on the connection:
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_sofia_callback: event nua_r_register: 408 Request Timeout
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_sofia_callback: connection 0x147f000, refcount 1
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_sofia_callback: dispatching to target 0x147f000 (handle 0x148ac10)
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_nua_r_register_cb: REGISTER failed, disconnecting
(telepathy-sofiasip:5855): tp-glib/connection-DEBUG: tp_base_connection_change_status: was 0, now 2, for reason 2
(telepathy-sofiasip:5855): tp-glib/connection-DEBUG: tp_base_connection_change_status: emitting status-changed to 2, for reason 2
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_disconnected: enter
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_disconnected: unregistering
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_shut_down: enter
(telepathy-sofiasip:5855): tp-glib/params-DEBUG: connection_shutdown_finished_cb: dereferenced connection
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_dispose: disposing of TpsipConnection 0x147f000
(telepathy-sofiasip:5855): tp-glib/sasl-DEBUG: tp_simple_password_manager_dispose: dispose called
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_finalize: enter
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_finalize: destroying sofia resolver
(telepathy-sofiasip:5855): tp-glib/connection-DEBUG: tp_contacts_mixin_finalize: 0x147f000
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_sofia_callback: exit
(telepathy-sofiasip:5855): tpsip-DEBUG: send 737 bytes to udp/[217.10.79.9]:5060 at 10:57:23.732858
and it's gone:
(telepathy-sofiasip:5855): tpsip-DEBUG: tpsip_connection_sofia_callback: event nua_r_shutdown: 200 Shutdown successful
(telepathy-sofiasip:5855): tpsip-DEBUG: priv_r_shutdown: forcing Sofia root GSource to be recursive
(telepathy-sofiasip:5855): tpsip-DEBUG: priv_r_shutdown: destroying Sofia-SIP NUA at address 0x1478d70
I'm using 1.12.11 and it works on my phone clients so there seems to be a bug in sofia-sip.
It seems to me that there is something else in the response that fools Sofia SIP to drop it into the bit bucket. For instance, Via line does not look very nice to me. The P-Registrar-Error indicates that Sofia has done some retransmissions here.
Please show the request triggering the response, and preferably enable full NTA logging with env variable NTA_DEBUG=9