GNOME Bugzilla – Bug 684435
cannot answer a call or initiate a call from call UI (but can from "new call" UI)
Last modified: 2013-06-23 17:03:22 UTC
I have one issue with sip (voice call) . If I use the "new call" (with a textentry autocompletion showing up) .... I can call (ie it popup the call ui and ring then my other phone ring and I can talk) . If the call UI is already up I cannot (ie either I receive a call , the call UI popup and I cannot ack ... well I can but it last less than one second before hangoout) (same issue if I attempt to call from the already opened call ui, hangout in less than a second) on the remote side (I tried with siproxyd in the middle ) I get a incoming call, then hang then ack.
I can confirm this. When I try to start a new outgoing call from the call window I get: empathy-Message: Element error: Failed to connect stream: Invalid argument -- pulsesrc.c(1505): gst_pulsesrc_prepare (): /GstPipeline:pipeline2/EmpathyGstAudioSrc:empathygstaudiosrc0/GstPulseSrc:pulsesrc0
(lt-empathy-call:19751): empathy-DEBUG: empathy_sound_play_internal: Play sound "phone-outgoing-calling" (Outgoing voice call) (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_poll_features: 0x2782420: request 0x4e3cb20 prepared (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_prepare_request_finish: 0x4e3cb20 (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_poll_features: 0x2782420: request 0x3937860 prepared (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_prepare_request_finish: 0x3937860 (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_poll_features: 0x7fbdf000def0: request 0x3965ae0 prepared (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_prepare_request_finish: 0x3965ae0 (lt-empathy-call:19751): tp-glib/debugger-DEBUG: generic_async_cb: Error: Invalid state for Accept (lt-empathy-call:19751): empathy-WARNING **: could not accept Call: Invalid state for Accept (lt-empathy-call:19751): empathy-DEBUG: empathy_call_window_conference_added_cb: Conference added (lt-empathy-call:19751): empathy-DEBUG: empathy_audio_src_set_echo_cancel: Src echo cancellation setting: on (lt-empathy-call:19751): empathy-DEBUG: empathy_audio_set_stream_properties: Echo cancellation: element allowed: yes, user enabled: yes (lt-empathy-call:19751): empathy-DEBUG: empathy_audio_sink_set_echo_cancel: Sink echo cancellation setting: on (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_poll_features: 0x3935170: request 0x393d5a0 prepared (lt-empathy-call:19751): tp-glib/proxy-DEBUG: tp_proxy_prepare_request_finish: 0x393d5a0 (lt-empathy-call:19751): tp-fs-DEBUG: Codecs changed (lt-empathy-call:19751): tp-fs-DEBUG: updating local codecs: 0 empathy-Message: Element error: Failed to connect stream: Invalid argument -- pulsesrc.c(1505): gst_pulsesrc_prepare (): /GstPipeline:pipeline3/EmpathyGstAudioSrc:empathygstaudiosrc0/GstPulseSrc:pulsesrc0 (lt-empathy-call:19751): empathy-DEBUG: playing_finished_cb: Error: Canceled (lt-empathy-call:19751): tp-fs-DEBUG: Transmitter: rawudp
Actually we have 2 errors here. The first time I try to re-call the contact I get this GStreamer error. empathy-Message: Element error: Failed to connect stream: Invalid argument -- pulsesrc.c(1505): gst_pulsesrc_prepare (): /GstPipeline:pipeline2/EmpathyGstAudioSrc:empathygstaudiosrc0/GstPulseSrc:pulsesrc0 Then for the second and next tries I get the Accept error and then the same gst one. (lt-empathy-call:15564): empathy-WARNING **: could not accept Call: Invalid state for Accept (expected: PENDING_INITIATOR, current: INITIALISING) Neither of those are SIP specific as I can reproduce calling the XMPP echo bot.
GST_DEBUG=3 logs of the gst bug: (lt-empathy-call:15752): empathy-DEBUG: empathy_call_window_conference_added_cb: Conference added 0:00:14.978980698 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<fsrtpconference1:sink_1> pad has no peer 0:00:14.980219477 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<send_rtp_capsfilter_1:sink> pad has no peer (lt-empathy-call:15752): empathy-DEBUG: empathy_audio_src_set_echo_cancel: Src echo cancellation setting: on (lt-empathy-call:15752): empathy-DEBUG: empathy_audio_set_stream_properties: Echo cancellation: element allowed: yes, user enabled: yes 0:00:14.981397481 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<send_tee_1:src_0> pad has no peer 0:00:14.982840437 15752 0x2127cf0 WARN default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<pulsesrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id 0:00:14.982909223 15752 0x2127cf0 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<send_tee_1:src_0> pad has no peer (lt-empathy-call:15752): empathy-DEBUG: empathy_audio_sink_set_echo_cancel: Sink echo cancellation setting: on (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_poll_features: 0x206a990: request 0x2137ac0 prepared 0:00:14.983098291 15752 0x2127cf0 WARN pulse pulsesrc.c:1505:gst_pulsesrc_prepare:<pulsesrc0> error: Failed to connect stream: Invalid argument (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_prepare_request_finish: 0x2137ac0 0:00:14.983206135 15752 0x2127cf0 WARN basesrc gstbasesrc.c:2775:gst_base_src_loop:<pulsesrc0> error: Internal data flow error. 0:00:14.983216635 15752 0x2127cf0 WARN basesrc gstbasesrc.c:2775:gst_base_src_loop:<pulsesrc0> error: streaming task paused, reason not-negotiated (-4) (lt-empathy-call:15752): tp-fs-DEBUG: Got MediaDescription /org/freedesktop/Telepathy/Connection/gabble/jabber/guillaume_2edesmottes_40collabora_2eco_2euk_2ff9a48ab7/CallChannel3/Content_audio_1/Offer0 (lt-empathy-call:15752): tp-fs-DEBUG: Delaying codec media_description processing (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_get_interface_by_id: 0x206a990: org.freedesktop.Telepathy.Call1.Stream.Interface.Media DBusGProxy is 0x23c4500 (lt-empathy-call:15752): tp-fs-DEBUG: Codecs changed (lt-empathy-call:15752): tp-fs-DEBUG: updating local codecs: 0 (lt-empathy-call:15752): tp-fs-DEBUG: Local codecs: (lt-empathy-call:15752): tp-fs-DEBUG: 96: audio SIREN clock:16000 channels:0 bitrate=16000 (lt-empathy-call:15752): tp-fs-DEBUG: 0: audio PCMU clock:8000 channels:0 (lt-empathy-call:15752): tp-fs-DEBUG: 8: audio PCMA clock:8000 channels:0 (lt-empathy-call:15752): tp-fs-DEBUG: 97: audio telephone-event clock:16000 channels:0 events=0-15 (lt-empathy-call:15752): tp-fs-DEBUG: 98: audio telephone-event clock:8000 channels:0 events=0-15 (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_get_interface_by_id: 0x7f3864002430: org.freedesktop.Telepathy.Call1.Stream.Endpoint DBusGProxy is 0x7f3868004960 (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_get_interface_by_id: 0x7f3864002430: org.freedesktop.DBus.Properties DBusGProxy is 0x23c4490 (lt-empathy-call:15752): tp-fs-DEBUG: Transmitter: nice: TpTransportType:3 controlling:0 (lt-empathy-call:15752): tp-fs-DEBUG: Requesting that the application start receiving (lt-empathy-call:15752): tp-fs-DEBUG: Request to start receiving succeeded 0:00:14.985107326 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<bin3:sink_1> pad has no peer 0:00:14.985421208 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<bin3:sink_2> pad has no peer 0:00:14.985647180 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<bin3:sink_2> pad has no peer 0:00:14.985680829 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<bin3:sink_1> pad has no peer 0:00:14.986611289 15752 0x7f3868001f20 WARN default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<nicesrc2:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id 0:00:14.986962612 15752 0x7f385c0020f0 WARN default gstutils.c:3622:gst_pad_create_stream_id_printf_valist:<nicesrc3:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id 0:00:14.987031418 15752 0x1c6bd80 WARN GST_PADS gstpad.c:3567:gst_pad_peer_query:<fsrtcpfilter1:sink> pad has no peer (lt-empathy-call:15752): tp-fs-DEBUG: updating local codecs: 0 (lt-empathy-call:15752): tp-fs-DEBUG: Local codecs: (lt-empathy-call:15752): tp-fs-DEBUG: 96: audio SIREN clock:16000 channels:0 bitrate=16000 (lt-empathy-call:15752): tp-fs-DEBUG: 0: audio PCMU clock:8000 channels:0 (lt-empathy-call:15752): tp-fs-DEBUG: 8: audio PCMA clock:8000 channels:0 (lt-empathy-call:15752): tp-fs-DEBUG: 97: audio telephone-event clock:16000 channels:0 events=0-15 (lt-empathy-call:15752): tp-fs-DEBUG: 98: audio telephone-event clock:8000 channels:0 events=0-15 (lt-empathy-call:15752): tp-fs-DEBUG: Accepting Media Description for contact: 27 (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_get_interface_by_id: 0x7f3860001900: org.freedesktop.Telepathy.Call1.Content.MediaDescription DBusGProxy is 0x7f38740019c0 (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_dispose: 0x7f3860001900 (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_invalidate: 0x7f3860001900: Proxy unreferenced (lt-empathy-call:15752): tp-glib/proxy-DEBUG: tp_proxy_finalize: 0x7f3860001900 (lt-empathy-call:15752): tp-fs-DEBUG: Got Endpoint Properties empathy-Message: Element error: Failed to connect stream: Invalid argument -- pulsesrc.c(1505): gst_pulsesrc_prepare (): /GstPipeline:pipeline2/EmpathyGstAudioSrc:empathygstaudiosrc0/GstPulseSrc:pulsesrc0
I reported the gst issue as bug #684469
Created attachment 224835 [details] [review] call-window: stop the call when we get a GStreamer error We have to properly terminate the call if something goes wrong at the GStreamer level. So, if we try to redial the contact, EmpathyCallHandler will request a fresh Call channel rather than trying to re-use the old one. Fix a warning when Accept() was failing when trying to re-accept a channel previously accepted.
The above patch doesn't solve this bug (the real issue is bug #684469) but at least fix the Accept() warning when trying to re-accept the channel.
Comment on attachment 224835 [details] [review] call-window: stop the call when we get a GStreamer error Patch reviewed by Sjoerd on IRC. No need to ask for a freeze exception for this as the root issue is in gst.
With the fix from this bug (Comment 6), from bug #684531 and gst-plugins-good master (to have bug #684469 fixed) this now works fine here. Could you apply those patches and retry please?
the log from the call ui while receiving a call from freephonie.net (too big for bugzilla, should I compress them and attach ?). http://prahal.homelinux.net/~prahal/gnome/empathy/0/ calllog_onlyrespondonce2.txt is the log from the call ui calllog_onlyrespondonce2_main.log.txt is the log from the main empathy window. (empathy-call:27891): tp-glib/debugger-DEBUG: call_state_changed_cb: Call state changed to ended (flags: 0) (empathy-call:27891): empathy-DEBUG: empathy_call_window_state_changed_cb: Call ended: unspecified reason seems to be the only relevant lines.
I added calllog_onlyrespondonce3_rakia.log at the same url I receive cancel sip message from the server 5 seconds after the invite session is initiated might be that the server expect a reply before this timeout otherwise it cancel and retry once , then redirect to the land line phone could empathy ack as soon as possible (before call ui is ready) ?
Olivier: does these logs ring any bell to you? Alban: could you try to reproduce the same scenario but using XMPP/Gtalk (and so Gabble) instead of SIP? If that works for you that's probably a rakia bug then.
For the pulsesrc error, please run "pulseaudio -vvvv" and attach the log (maybe to a new bug?) If the state is INITIALISING, it means someone else called accept, so it should fine. The timeout should be a lot more than 5 seconds for SIP INVITE, unless I missed something
sorry confused the pulse error is fixed . Workaround in gstreamer 1.0 waiting for a fixed pulseaudio. Was your comment about above traces (inline in the bug report) or http://prahal.homelinux.net/~prahal/gnome/empathy/0/ traces ?
Today I did : GST_DEBUG="fsrtpconference*:6" EMPATHY_PERSIST=1 /opt/gnome/libexec/empathy-call and got: 0:00:11.691656212 28365 0x110fe90 LOG fsrtpconference_disco /home/prahal/Projects/Devel/Gnome/jhbuild/gnome/farstream-0.2.2/gst/fsrtpconference/fs-rtp-discover-codecs.c:125:debug_codec_cap: 0x1c87000:1:rtp_caps application/x-rtp, media=(string)audio, payload=(int)12, clock-rate=(int)8000; application/x-rtp, media=(string)audio, clock-rate=(int)8000, encoding-name=(string)QCELP ** ERROR:/home/prahal/Projects/Devel/Gnome/jhbuild/gnome/farstream-0.2.2/gst/fsrtpconference/fs-rtp-discover-codecs.c:127:debug_codec_cap: assertion failed: (gst_caps_get_size (codec_cap->rtp_caps) == 1) then abort. then: UAC terminate the call when so. SIP 484 Status: 100 Trying | SIP 569 Status: 480 Terminated | So this is not a bug in empathy but in farstream . There are two caps and farstream assert if there are two . I cannot tell why so I removed the assert and all is fine now.
This is fixed in Farstream 0.2.3