Re: Lost microphone, some news

On Wed, 2018-06-27 at 11:33 +1200, Eion Robb wrote:
> Hi Jocke,
> 
> The devel@ mailing list might be more appropriate to discuss code and
> technical changes.  You might also want to get in touch with the sipe
> plugin developers on their forum, as I don't believe the monitor the
> Pidgin mailing lists.

I suspect it isn't SIPE-specific; I'm seeing something fairly similar
with Chime. Sometimes, the pulsesrc element just stops feeding me data.

https://bugzilla.gnome.org/show_bug.cgi?id=795374

I tried a hack to set the pipeline into PLAYING later, in an attempt to
make it go away. It made it happen 100% of the time instead. Which I
suppose is a step towards diagnosing it...

I think this is the hack I had at the time; I need to get back to it
now I've fixed the more important problem of the incoming audio going
away (which required a Pidgin restart to fix it; this one just needs me
to close the call and rejoin it).

Added Jan to Cc since he seemed to have coherent thoughts about this
when I first reported it.

> On Wed, 27 Jun 2018 at 03:39, Joakim Tjernlund <[email protected]> wrote:
> > I loose my microphone(USB headset) on and off. Fairly easy to trigger doing SIPE Test Calls
> > I have debugged it with GST_DEBUG=3 to:
> > 0:01:44.674183639  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.674222435  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.723644690  9191 0x7f7750005370 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.723684456  9191 0x7f7750005370 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.773257417  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.773299667  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.773345513  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.773362553  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.773552549  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.773577829  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.824544605  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.824593763  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:44.984509825  9191 0x7f7750005370 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:44.984555736  9191 0x7f7750005370 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:45.038746276  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:686:validate_buffer: No SSRC found in buffer
> > 0:01:45.038816916  9191 0x55f2eff3f0f0 WARN                 srtpdec gstsrtpdec.c:1254:gst_srtp_dec_chain: Invalid buffer, dropping
> > 0:01:45.214407207  9191 0x55f2f0c30400 FIXME               basesink gstbasesink.c:3144:gst_base_sink_default_event: stream-start event without group-id. Consider implementing group-id handling in the upstream elements
> > 0:01:45.297601562  9191 0x7f7784025a40 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb: Got underflow
> > 0:01:53.676467518  9191 0x7f7784025a40 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb: Got underflow
> > 0:02:10.626495331  9191 0x7f7784025a40 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb: Got underflow
> > 0:02:11.988072210  9191 0x7f7784025a40 WARN                   pulse pulsesink.c:702:gst_pulsering_stream_underflow_cb: Got underflow
> > 0:02:15.532355085  9191 0x7f7750004b70 WARN                   pulse pulsesrc.c:1141:gst_pulsesrc_read: error: pa_pause2: OK
> > 0:02:15.532500956  9191 0x7f7750004b70 WARN                   pulse pulsesrc.c:1204:gst_pulsesrc_read: error: pa_unlock_and_fail: OK
> > 0:02:15.532584089  9191 0x7f7750004b70 WARN                audiosrc gstaudiosrc.c:221:audioringbuffer_thread_func: error reading data -1 (reason: Resource temporarily unavailable), skipping segment
> > 
> > Here I loose my microphone and further(with some extra debug in gstreamer, pulsesrc.c:
> > gst_pulsesrc_read()
> > ....
> > while (length > 0) {
> >     size_t l;
> > 
> >     GST_LOG_OBJECT (pulsesrc, "reading %u bytes", length);
> > 
> >     /*check if we have a leftover buffer */
> >     if (!pulsesrc->read_buffer) {
> >       for (;;) {
> >           if (gst_pulsesrc_is_dead (pulsesrc, TRUE)) {
> >               GST_ELEMENT_ERROR (pulsesrc, RESOURCE, FAILED,
> >                                  ("pa_dead: %s",
> >                                   pa_strerror (pa_context_errno (pulsesrc->context))), (NULL));
> >               goto unlock_and_fail;
> >           }
> > 
> >         /* read all available data, we keep a pointer to the data and the length
> >          * and take from it what we need. */
> >         if (pa_stream_peek (pulsesrc->stream, &pulsesrc->read_buffer,
> >                 &pulsesrc->read_buffer_length) < 0)
> >           goto peek_failed;
> > 
> >         GST_LOG_OBJECT (pulsesrc, "have data of %" G_GSIZE_FORMAT " bytes",
> >             pulsesrc->read_buffer_length);
> > 
> >         /* if we have data, process if */
> >         if (pulsesrc->read_buffer && pulsesrc->read_buffer_length)
> >           break;
> > 
> >         /* now wait for more data to become available */
> >         GST_LOG_OBJECT (pulsesrc, "waiting for data");
> >         pa_threaded_mainloop_wait (pulsesrc->mainloop);
> > 
> >         if (pulsesrc->paused) {
> >             GST_ELEMENT_ERROR (pulsesrc, RESOURCE, FAILED,
> >                                ("pa_pause2: %s",
> >                                 pa_strerror (pa_context_errno (pulsesrc->context))), (NULL));
> >             goto was_paused;
> >         }
> >       }
> >     }
> > 
> > .....
> > unlock_and_fail:
> >   {
> >     GST_ELEMENT_ERROR (pulsesrc, RESOURCE, FAILED,
> >         ("pa_unlock_and_fail: %s",
> >             pa_strerror (pa_context_errno (pulsesrc->context))), (NULL));
> >     pulsesrc->in_read = FALSE;
> >     pa_threaded_mainloop_unlock (pulsesrc->mainloop);
> > 
> >     return (guint) - 1;
> >   }
> > }
> > 
> > Here one can se that whenever pause happens, I loose audio.
> > I don't know where to go next, this is audioringbuffer_thread_func()
> > in gstaudiosrc.c:
> > ....
> > do {
> >         read = readfunc (src, readptr, left, ×tamp);
> >         GST_LOG_OBJECT (src, "transfered %d bytes of %d to segment %d", read,
> >             left, readseg);
> >         if (read < 0 || read > left) {
> >           GST_WARNING_OBJECT (src,
> >               "error reading data %d (reason: %s), skipping segment", read,
> >               g_strerror (errno));
> >           break;
> >         }
> >         left -= read;
> >         readptr += read;
> > } while (left > 0);
> > 
> >       /* Update timestamp on buffer if required */
> >       gst_audio_ring_buffer_set_timestamp (buf, readseg, timestamp);
> > 
> >       /* we read one segment */
> >       gst_audio_ring_buffer_advance (buf, 1);
> > ....
> > No idea if pause should be handle here or maybe somewhere in pidgin,pidgin-sipe ?
> > 
> >  Jocke
> > _______________________________________________
> > [email protected] mailing list
> > Want to unsubscribe?  Use this link:
> > https://pidgin.im/cgi-bin/mailman/listinfo/support
> _______________________________________________
> Devel mailing list
> [email protected]
> https://pidgin.im/cgi-bin/mailman/listinfo/devel

_______________________________________________
Devel mailing list
[email protected]
https://pidgin.im/cgi-bin/mailman/listinfo/devel

diff --git a/libpurple/media/backend-fs2.c b/libpurple/media/backend-fs2.c
index c9d806b..a352c9b 100644
--- a/libpurple/media/backend-fs2.c
+++ b/libpurple/media/backend-fs2.c
@@ -993,7 +993,7 @@ gst_handle_message_element(GstBus *bus, GstMessage *msg,
 	GstElement *src = GST_ELEMENT(GST_MESSAGE_SRC(msg));
 	static guint level_id = 0;
 	const GstStructure *structure = gst_message_get_structure(msg);
-
+	purple_debug_info("backend-fs2", "message: %s\n", gst_structure_get_name(structure));
 	if (level_id == 0)
 		level_id = g_signal_lookup("level", PURPLE_TYPE_MEDIA);
 
@@ -1244,6 +1244,8 @@ gst_handle_message_element(GstBus *bus, GstMessage *msg,
 			"farstream-recv-codecs-changed")) {
 #endif
 		const GValue *value;
+		FsStream *stream;
+		PurpleMediaBackendFs2Session *session;
 		GList *codecs;
 		FsCodec *codec;
 
@@ -1258,6 +1260,16 @@ gst_handle_message_element(GstBus *bus, GstMessage *msg,
 				"farstream-recv-codecs-changed: %s\n",
 #endif
 				codec->encoding_name);
+
+		value = gst_structure_get_value(structure, "stream");
+		stream = g_value_get_object(value);
+		session = get_session_from_fs_stream(self, stream);
+
+		purple_debug_info("backend-fs2", "create_src: setting source "
+				   "state to GST_STATE_PLAYING - it may hang here on win32\n");
+		gst_element_set_state(session->src, GST_STATE_PLAYING);
+		purple_debug_info("backend-fs2", "create_src: state set\n");
+
 	} else if (gst_structure_has_name(structure,
 #ifdef HAVE_FARSIGHT
 			"farsight-component-state-changed")) {
@@ -1315,6 +1327,8 @@ gst_handle_message_element(GstBus *bus, GstMessage *msg,
 		const GValue *value;
 		FsCodec *codec;
 		gchar *codec_str;
+		FsSession *fssession;
+		GList *sessions;
 
 		value = gst_structure_get_value(structure, "codec");
 		codec = g_value_get_boxed(value);
@@ -1329,6 +1343,30 @@ gst_handle_message_element(GstBus *bus, GstMessage *msg,
 				codec_str);
 
 		g_free(codec_str);
+
+		value = gst_structure_get_value(structure, "session");
+		fssession = g_value_get_object(value);
+
+		sessions = g_hash_table_get_values(priv->sessions);
+
+		for (; sessions; sessions =
+				g_list_delete_link(sessions, sessions)) {
+			PurpleMediaBackendFs2Session *session = sessions->data;
+
+			if (session->session != fssession)
+				continue;
+
+			purple_debug_info("backend-fs2", "create_src: setting source AGAIN"
+					  "state to GST_STATE_PLAYING - it may hang here on win32\n");
+			gst_element_set_state(session->src, GST_STATE_READY);
+			gst_element_set_state(session->src, GST_STATE_PLAYING);
+			purple_debug_info("backend-fs2", "create_src: state set\n");
+
+			g_list_free(sessions);
+			break;
+		}
+
+
 	} else if (gst_structure_has_name(structure,
 #ifdef HAVE_FARSIGHT
 			"farsight-codecs-changed")) {
@@ -1895,11 +1933,6 @@ create_src(PurpleMediaBackendFs2 *self, const gchar *sess_id,
 	purple_media_manager_create_output_window(purple_media_get_manager(
 			priv->media), priv->media, sess_id, NULL);
 
-	purple_debug_info("backend-fs2", "create_src: setting source "
-		"state to GST_STATE_PLAYING - it may hang here on win32\n");
-	gst_element_set_state(session->src, GST_STATE_PLAYING);
-	purple_debug_info("backend-fs2", "create_src: state set\n");
-
 	return TRUE;
 }