No early media after SIP 183
Hello,
When using
from
https://dl.jami.net/nightly/debian_10/pool/main/j/jami/
in Debian 10, Jami does not play ringback when calling external number (which uses SIP 183 message when waiting for call to be picked up and early media/SDP); when call is picked up - voice is played correctly; dring debug log of such call:
[1600086622.792|15229|manager.cpp :581 ] ----- Switch current call id to '2159493006188118' -----
[1600086622.792|15230|sipcall.cpp :963 ] [call:2159493006188118] fill SDP with ICE transport 0x5633ef823740
[1600086622.792|15230|sipaccount.cpp :375 ] contact header: "test" <sip:login@192.168.1.100:5060> / "test" <sip:login@sip.mydomain.loc> -> <sip:111222333@sip.mydomain.loc>
[1600086622.792|15230|sipvoiplink.cpp :853 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 state changed to 1 (CALLING): cause=0, tsx@0x7fd6dc048e88 status 0 (Default status message)
[1600086622.793|15230|call.cpp :259 ] [call:2159493006188118] state change 0/1, cnx 0/2, code 0
[1600086622.793|15230|call.cpp :286 ] [call:2159493006188118] emit client call state change CONNECTING, code 0
[1600086624.793|15230|call.cpp :112 ] Call 2159493006188118 is still connecting after timeout, sending fallback request
[1600086625.482|15233|sipvoiplink.cpp :853 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 state changed to 3 (EARLY): cause=0, tsx@0x7fd70800d278 status 183 (Session Progress)
[1600086625.482|15233|sipvoiplink.cpp :1009 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 media update: status 0
[1600086625.482|15233|sdp.cpp :383 ] Local active SDP Session:
v=0
o=ibnb003 3809075422 0 IN IP4 192.168.1.100
s=Jami Daemon
c=IN IP4 192.168.1.100
t=0 0
a=ice-ufrag:1d26a479
a=ice-pwd:33f8ac4760b4c6501dd61dfa
m=audio 41884 RTP/AVP 110 101
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:41885 IN IP4 192.168.1.100
a=sendrecv
a=candidate:H44e08c2a 1 UDP 2130706431 [...] 42537 typ host
a=candidate:Ha030271 1 UDP 2130706431 192.168.1.100 39418 typ host
a=candidate:Hc0a87b64 1 UDP 2130706175 [...] 39418 typ host
a=candidate:Hc0a87a01 1 UDP 2130705919 [...] 39418 typ host
a=candidate:H44e08c2a 2 UDP 2130706430 [...] 42180 typ host
a=candidate:Ha030271 2 UDP 2130706430 [...] 35281 typ host
a=candidate:Hc0a87b64 2 UDP 2130706174 [...] 35281 typ host
a=candidate:Hc0a87a01 2 UDP 2130705918 [...] 35281 typ host
m=video 0 RTP/AVP 96 97 98 99
[1600086625.482|15233|sdp.cpp :383 ] Remote active SDP Session:
v=0
o=ib 1858813877 1858813877 IN IP4 192.168.100.2
s=IB VoIP Server
c=IN IP4 192.168.100.2
t=0 0
m=audio 23562 RTP/AVP 110 101
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=maxptime:60
a=sendrecv
m=video 0 RTP/AVP 96 97 98 99
[1600086625.482|15233|sipcall.cpp :1230 ] [call:2159493006188118] medias changed
[1600086625.482|15230|sipcall.cpp :1242 ] [call:2159493006188118] no remote ICE for medias
[1600086625.482|15230|sipcall.cpp :1182 ] [call:2159493006188118] stopping all medias
[1600086625.482|15230|sipcall.cpp :1021 ] [call:2159493006188118] startAllMedia()
[1600086625.482|15230|socket_pair.cpp :172 ] use local address: 0.0.0.0:41884
[1600086625.482|15230|socket_pair.cpp :172 ] use local address: 0.0.0.0:41885
[1600086625.482|15230|socket_pair.cpp :349 ] SocketPair: local{41884,41885} / 192.168.100.2{23562,23563}
[1600086625.482|15230|audio_input.cpp :53 ] Creating audio input with id: 2159493006188118
[1600086625.483|15230|audio_input.cpp :270 ] Switching audio source to match 'camera://04f2b3ec200901010001'
[1600086625.483|15230|audio_sender.cpp :72 ] audioEncoder_->openOutput rtp://192.168.100.2:23562
[1600086625.483|15230|media_encoder.cpp :268 ] Not using hardware encoding for speex
[1600086625.483|15230|media_encoder.cpp :574 ] [libspeex] Using 4 threads
[1600086625.483|15230|media_encoder.cpp :621 ] [libspeex] Frame size 160
[1600086625.483|15230|sipcall.cpp :1065 ] [call:2159493006188118] [SDP:slot#1] Missing local codec
[1600086625.483|16375|media_decoder.cpp :134 ] Trying to open device dummyFilename with format sdp, pixel format , size 0x0, rate 0.000000
[1600086625.483|16375|media_decoder.cpp :146 ] Using format sdp
[1600086625.503|16374|audio_input.cpp :76 ] Switching audio input to '04f2b3ec200901010001'
[1600086628.306|15233|sipvoiplink.cpp :853 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 state changed to 4 (CONNECTING): cause=0, tsx@0x7fd70800d278 status 200 (OK)
[1600086628.306|15233|sipvoiplink.cpp :1009 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 media update: status 0
[1600086628.306|15233|sdp.cpp :383 ] Local active SDP Session:
v=0
o=ibnb003 3809075422 1 IN IP4 192.168.1.100
s=Jami Daemon
c=IN IP4 192.168.1.100
t=0 0
a=ice-ufrag:1d26a479
a=ice-pwd:33f8ac4760b4c6501dd61dfa
m=audio 41884 RTP/AVP 110 101
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:41885 IN IP4 192.168.1.100
a=sendrecv
a=candidate:H44e08c2a 1 UDP 2130706431 [...] 42537 typ host
a=candidate:Ha030271 1 UDP 2130706431 [...] 39418 typ host
a=candidate:Hc0a87b64 1 UDP 2130706175 [...] 39418 typ host
a=candidate:Hc0a87a01 1 UDP 2130705919 [...] 39418 typ host
a=candidate:H44e08c2a 2 UDP 2130706430 [...] 42180 typ host
a=candidate:Ha030271 2 UDP 2130706430 [...] 35281 typ host
a=candidate:Hc0a87b64 2 UDP 2130706174 [...] 35281 typ host
a=candidate:Hc0a87a01 2 UDP 2130705918 [...] 35281 typ host
m=video 0 RTP/AVP 96 97 98 99
[1600086628.306|15233|sdp.cpp :383 ] Remote active SDP Session:
v=0
o=ib 1858813877 1858813877 IN IP4 192.168.100.2
s=IB VoIP Server
c=IN IP4 192.168.100.2
t=0 0
m=audio 23562 RTP/AVP 110 101
a=rtpmap:110 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=maxptime:60
a=sendrecv
m=video 0 RTP/AVP 96 97 98 99
[1600086628.306|15233|sipcall.cpp :1230 ] [call:2159493006188118] medias changed
[1600086628.306|15230|sipcall.cpp :1242 ] [call:2159493006188118] no remote ICE for medias
[1600086628.306|15230|sipcall.cpp :1182 ] [call:2159493006188118] stopping all medias
[1600086628.306|15233|sipvoiplink.cpp :861 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 state changed to 5 (CONFIRMED): cause=0 (TX_MSG)
[1600086628.306|15233|sipcall.cpp :910 ] [call:2159493006188118] onAnswered()
[sdp @ 0x7fd6bc0206c0] Could not find codec parameters for stream 0 (Audio: speex (libspeex), 8000 Hz, mono): unspecified sample format
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[1600086628.387|16375|media_decoder.cpp :481 ] Decoding audio using libspeex Speex (libspeex)
[1600086628.387|16375|media_decoder.cpp :491 ] Not using hardware decoding for speex
[1600086628.387|15230|sipcall.cpp :1021 ] [call:2159493006188118] startAllMedia()
[1600086628.387|15230|socket_pair.cpp :172 ] use local address: 0.0.0.0:41884
[1600086628.387|15230|socket_pair.cpp :172 ] use local address: 0.0.0.0:41885
[1600086628.387|15230|socket_pair.cpp :349 ] SocketPair: local{41884,41885} / 192.168.100.2{23562,23563}
[1600086628.387|15230|audio_input.cpp :270 ] Switching audio source to match 'camera://04f2b3ec200901010001'
[1600086628.387|15230|audio_sender.cpp :72 ] audioEncoder_->openOutput rtp://192.168.100.2:23562
[1600086628.387|15230|media_encoder.cpp :268 ] Not using hardware encoding for speex
[1600086628.387|15230|media_encoder.cpp :574 ] [libspeex] Using 4 threads
[1600086628.387|15230|media_encoder.cpp :621 ] [libspeex] Frame size 160
[1600086628.387|15230|sipcall.cpp :1065 ] [call:2159493006188118] [SDP:slot#1] Missing local codec
[1600086628.387|16376|media_decoder.cpp :134 ] Trying to open device dummyFilename with format sdp, pixel format , size 0x0, rate 0.000000
[1600086628.387|15230|call.cpp :259 ] [call:2159493006188118] state change 1/1, cnx 2/4, code 0
[1600086628.387|15230|call.cpp :286 ] [call:2159493006188118] emit client call state change CURRENT, code 0
[1600086628.387|16376|media_decoder.cpp :146 ] Using format sdp
[1600086628.387|15230|manager.cpp :2007 ] [call:2159493006188118] Peer answered
[1600086628.387|15230|manager.cpp :1631 ] Add audio to call 2159493006188118
[1600086628.387|15230|manager.cpp :1645 ] [call:2159493006188118] Attach audio
[1600086628.387|15230|ringbufferpool.cpp:175 ] Bind call 2159493006188118 to call audiolayer_id
[1600086628.387|15230|ringbufferpool.cpp:156 ] Bind rbuf '2159493006188118' to callid 'audiolayer_id'
[1600086628.387|15230|ringbufferpool.cpp:156 ] Bind rbuf 'audiolayer_id' to callid '2159493006188118'
[1600086628.387|15230|audiolayer.cpp :130 ] Hardware audio format available : {s16, 2 channels, 44100Hz} 0
[1600086628.387|15230|audiostream.cpp :53 ] Playback: trying to create stream with device alsa_output.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback (44100Hz, 1 channels)
[1600086628.387|15230|audiostream.cpp :148 ] Stream is creating...
[1600086628.387|15230|audiostream.cpp :53 ] Ringtone: trying to create stream with device (44100Hz, 2 channels)
[1600086628.387|15230|audiostream.cpp :148 ] Stream is creating...
[1600086628.387|15230|audiostream.cpp :53 ] Capture: trying to create stream with device alsa_input.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback (44100Hz, 1 channels)
[1600086628.387|15230|audiostream.cpp :148 ] Stream is creating...
[1600086628.403|16374|audio_input.cpp :76 ] Switching audio input to '04f2b3ec200901010001'
[1600086629.465|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_output.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback
[1600086629.465|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_output.pci-0000_00_1b.0.analog-stereo
[1600086629.465|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_input.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback
[1600086629.465|15245|pulselayer.cpp :371 ] All streams ready, starting !
[1600086629.588|16376|media_decoder.cpp :481 ] Decoding audio using libspeex Speex (libspeex)
[1600086629.588|16376|media_decoder.cpp :491 ] Not using hardware decoding for speex
[1600086634.112|15233|sipvoiplink.cpp :853 ] [call:2159493006188118] INVITE@0x7fd6dc010a48 state changed to 6 (DISCONNCTD): cause=200, tsx@0x7fd70800d278 status 200 (OK)
[1600086634.112|15230|manager.cpp :2040 ] [call:2159493006188118] Peer hungup
Problem does not occur on same Debian system and SIP account when using Twinkle SIP client.
Problem does not occur in Jami when local VoiP number is called (which uses SIP 180 message when waiting for call, without early media/SDP); dring debug log of such /not answered/ call when ringback was played correctly:
[1600085689.195|15229|manager.cpp :581 ] ----- Switch current call id to '5190575654160253' -----
[1600085689.195|15230|sipcall.cpp :963 ] [call:5190575654160253] fill SDP with ICE transport 0x5633ef824e50
[1600085689.195|15230|sdp.cpp :718 ] addIceCandidates failed: cannot access media#1 (may be deactivated)
[1600085689.196|15230|sdp.cpp :718 ] addIceCandidates failed: cannot access media#1 (may be deactivated)
[1600085689.196|15230|sipaccount.cpp :375 ] contact header: "test" <sip:login@129.168.1.100:5060> / "IB" <sip:login@sip.mydomain.loc> -> <sip:login2@sip.mydomain.loc>
[1600085689.196|15230|sipvoiplink.cpp :853 ] [call:5190575654160253] INVITE@0x7fd6dc0460b8 state changed to 1 (CALLING): cause=0, tsx@0x7fd6dc0286b8 status 0 (Default status message)
[1600085689.196|15230|call.cpp :259 ] [call:5190575654160253] state change 0/1, cnx 0/2, code 0
[1600085689.196|15230|call.cpp :286 ] [call:5190575654160253] emit client call state change CONNECTING, code 0
[1600085689.374|15233|sipvoiplink.cpp :853 ] [call:5190575654160253] INVITE@0x7fd6dc0460b8 state changed to 3 (EARLY): cause=0, tsx@0x7fd70800d278 status 180 (Ringing)
[1600085689.374|15233|call.cpp :259 ] [call:5190575654160253] state change 1/1, cnx 2/3, code 0
[1600085689.374|15233|call.cpp :286 ] [call:5190575654160253] emit client call state change RINGING, code 0
[1600085689.374|15230|manager.cpp :2029 ] [call:5190575654160253] Peer ringing
[1600085689.374|15230|audiolayer.cpp :130 ] Hardware audio format available : {s16, 2 channels, 44100Hz} 0
[1600085689.374|15230|audiostream.cpp :53 ] Playback: trying to create stream with device alsa_output.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback (44100Hz, 1 channels)
[1600085689.374|15230|audiostream.cpp :148 ] Stream is creating...
[1600085689.374|15230|audiostream.cpp :53 ] Ringtone: trying to create stream with device (44100Hz, 2 channels)
[1600085689.374|15230|audiostream.cpp :148 ] Stream is creating...
[1600085689.374|15230|audiostream.cpp :53 ] Capture: trying to create stream with device alsa_input.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback (44100Hz, 1 channels)
[1600085689.374|15230|audiostream.cpp :148 ] Stream is creating...
[1600085690.454|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_output.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback
[1600085690.454|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_output.pci-0000_00_1b.0.analog-stereo
[1600085690.454|15245|audiostream.cpp :156 ] Stream successfully created, connected to alsa_input.usb-GN_Netcom_A_S_Jabra_PRO_930_027608F15805-00.mono-fallback
[1600085690.454|15245|pulselayer.cpp :371 ] All streams ready, starting !
[1600085697.904|15229|manager.cpp :1665 ] [call:5190575654160253] Remove local audio
[1600085697.904|15229|ringbufferpool.cpp:242 ] Unbind call 5190575654160253 from all bound calls
[1600085697.904|15229|sipcall.cpp :368 ] [call:5190575654160253] Terminate SIP session
It seems that Jami has problem playing early media from SDP after 183 SIP message (opening sound device problem maybe?) and has not such problem when self playing ringback tone after 180 SIP message.
Sound configuration is pulseaudio, rindtone device = default (uses standard speakers), output and input devices = Jabra PRO 930 Mono and works ok in other functions (i.e. incomming ringing on standard speakers but ringback tones and speech on Jabra).
Regards, Paweł