MT#57093 log reasons for unkernel event

Change-Id: I4148c9d13308bbb1cc8ec7ae603fde8503b5ec9a

daemon/call.c

@@ -3487,14 +3487,14 @@ int monologue_subscribe_answer(struct call_monologue *dst_ml, struct sdp_ng_flag
 	}
 
 	__update_init_subscribers(dst_ml, streams, flags, flags->opmode);
-	dialogue_unkernelize(dst_ml);
+	dialogue_unkernelize(dst_ml, "subscribe answer event");
 
 	for (GList *l = dst_ml->subscriptions.head; l; l = l->next) {
 		struct call_subscription *cs = l->data;
 		struct call_monologue *src_ml = cs->monologue;
 		set_transcoding_flag(src_ml, dst_ml, transcoding);
 		__update_init_subscribers(src_ml, NULL, NULL, flags->opmode);
-		dialogue_unkernelize(src_ml);
+		dialogue_unkernelize(src_ml, "subscribe answer event");
 	}
 
 	return 0;
@@ -3512,8 +3512,8 @@ int monologue_unsubscribe(struct call_monologue *dst_ml, struct sdp_ng_flags *fl
 		__update_init_subscribers(dst_ml, NULL, NULL, flags->opmode);
 		__update_init_subscribers(src_ml, NULL, NULL, flags->opmode);
 
-		dialogue_unkernelize(src_ml);
-		dialogue_unkernelize(dst_ml);
+		dialogue_unkernelize(src_ml, "monologue unsubscribe");
+		dialogue_unkernelize(dst_ml, "monologue unsubscribe");
 
 		l = next;
 	}
@@ -3601,7 +3601,7 @@ static void __call_cleanup(struct call *c) {
 
 		send_timer_put(&ps->send_timer);
 		jb_put(&ps->jb);
-		__unkernelize(ps);
+		__unkernelize(ps, "final call cleanup");
 		dtls_shutdown(ps);
 		ps->selected_sfd = NULL;
 		g_queue_clear(&ps->sfds);
@@ -4155,14 +4155,14 @@ void __monologue_viabranch(struct call_monologue *ml, const str *viabranch) {
 	g_hash_table_insert(call->viabranches, &ml->viabranch, ml);
 }
 
-static void __unconfirm_sinks(GQueue *q) {
+static void __unconfirm_sinks(GQueue *q, const char *reason) {
 	for (GList *l = q->head; l; l = l->next) {
 		struct sink_handler *sh = l->data;
-		__stream_unconfirm(sh->sink);
+		__stream_unconfirm(sh->sink, reason);
 	}
 }
 /* must be called with call->master_lock held in W */
-void __monologue_unkernelize(struct call_monologue *monologue) {
+void __monologue_unkernelize(struct call_monologue *monologue, const char *reason) {
 	if (!monologue)
 		return;
 
@@ -4173,41 +4173,41 @@ void __monologue_unkernelize(struct call_monologue *monologue) {
 
 		for (GList *m = media->streams.head; m; m = m->next) {
 			struct packet_stream *stream = m->data;
-			__stream_unconfirm(stream);
-			__unconfirm_sinks(&stream->rtp_sinks);
-			__unconfirm_sinks(&stream->rtcp_sinks);
+			__stream_unconfirm(stream, reason);
+			__unconfirm_sinks(&stream->rtp_sinks, reason);
+			__unconfirm_sinks(&stream->rtcp_sinks, reason);
 		}
 	}
 }
-void dialogue_unkernelize(struct call_monologue *ml) {
-	__monologue_unkernelize(ml);
+void dialogue_unkernelize(struct call_monologue *ml, const char *reason) {
+	__monologue_unkernelize(ml, reason);
 
 	for (GList *sub = ml->subscriptions.head; sub; sub = sub->next) {
 		struct call_subscription *cs = sub->data;
-		__monologue_unkernelize(cs->monologue);
+		__monologue_unkernelize(cs->monologue, reason);
 	}
 	for (GList *sub = ml->subscribers.head; sub; sub = sub->next) {
 		struct call_subscription *cs = sub->data;
-		__monologue_unkernelize(cs->monologue);
+		__monologue_unkernelize(cs->monologue, reason);
 	}
 }
 
-static void __unkernelize_sinks(GQueue *q) {
+static void __unkernelize_sinks(GQueue *q, const char *reason) {
 	for (GList *l = q->head; l; l = l->next) {
 		struct sink_handler *sh = l->data;
-		unkernelize(sh->sink);
+		unkernelize(sh->sink, reason);
 	}
 }
 /* call locked in R */
-void call_media_unkernelize(struct call_media *media) {
+void call_media_unkernelize(struct call_media *media, const char *reason) {
 	GList *m;
 	struct packet_stream *stream;
 
 	for (m = media->streams.head; m; m = m->next) {
 		stream = m->data;
-		unkernelize(stream);
-		__unkernelize_sinks(&stream->rtp_sinks);
-		__unkernelize_sinks(&stream->rtcp_sinks);
+		unkernelize(stream, reason);
+		__unkernelize_sinks(&stream->rtp_sinks, reason);
+		__unkernelize_sinks(&stream->rtcp_sinks, reason);
 	}
 }
 
@@ -4230,7 +4230,7 @@ void monologue_destroy(struct call_monologue *monologue) {
 			STR_FMT(&monologue->tag),
 			STR_FMT0(&monologue->viabranch));
 
-	__monologue_unkernelize(monologue);
+	__monologue_unkernelize(monologue, "destroying monologue");
 	__tags_unassociate_all(monologue);
 
 	g_hash_table_remove(call->tags, &monologue->tag);
@@ -4375,10 +4375,10 @@ static int call_get_monologue_new(struct call_monologue *dialogue[2], struct cal
 	}
 
 	__C_DBG("found existing monologue");
-	__monologue_unkernelize(ret);
+	__monologue_unkernelize(ret, "signalling on existing monologue");
 	for (GList *sub = ret->subscriptions.head; sub; sub = sub->next) {
 		struct call_subscription *cs = sub->data;
-		__monologue_unkernelize(cs->monologue);
+		__monologue_unkernelize(cs->monologue, "signalling on existing monologue");
 	}
 
 	/* If we have a to-tag, confirm that this dialogue association is intact.
@@ -4399,7 +4399,7 @@ static int call_get_monologue_new(struct call_monologue *dialogue[2], struct cal
 				if (!csm)
 					goto new_branch;
 				// use existing to-tag
-				__monologue_unkernelize(csm);
+				__monologue_unkernelize(csm, "dialogue association changed");
 				__subscribe_offer_answer_both_ways(ret, csm);
 				break;
 			}
@@ -4428,7 +4428,7 @@ static int call_get_monologue_new(struct call_monologue *dialogue[2], struct cal
 	os = g_hash_table_lookup(call->viabranches, viabranch);
 	if (os) {
 		/* previously seen branch. use it */
-		__monologue_unkernelize(os);
+		__monologue_unkernelize(os, "dialogue/branch association changed");
 		__subscribe_offer_answer_both_ways(ret, os);
 		goto ok_check_tag;
 	}
@@ -4535,13 +4535,13 @@ tag_setup:
 	if (!ft->tag.s || str_cmp_str(&ft->tag, fromtag))
 		__monologue_tag(ft, fromtag);
 
-	dialogue_unkernelize(ft);
-	dialogue_unkernelize(tt);
+	dialogue_unkernelize(ft, "dialogue signalling event");
+	dialogue_unkernelize(tt, "dialogue signalling event");
 	__subscribe_offer_answer_both_ways(ft, tt);
 
 done:
-	__monologue_unkernelize(ft);
-	dialogue_unkernelize(ft);
+	__monologue_unkernelize(ft, "dialogue signalling event");
+	dialogue_unkernelize(ft, "dialogue signalling event");
 	__tags_associate(ft, tt);
 	dialogue[0] = ft;
 	dialogue[1] = tt;

daemon/call_interfaces.c

@@ -2646,7 +2646,7 @@ found:
 			return "From-tag given, but no such tag exists";
 	}
 	if (*monologue)
-		__monologue_unkernelize(*monologue);
+		__monologue_unkernelize(*monologue, "media blocking signalling event");
 	return NULL;
 }
 static const char *media_block_match(struct call **call, struct call_monologue **monologue,
@@ -3024,7 +3024,7 @@ static const char *call_block_silence_media(bencode_item_t *input, bool on_off,
 					STR_FMT_M(&monologue->tag));
 			G_STRUCT_MEMBER(bool, monologue, ml_offset) = on_off;
 		}
-		__monologue_unkernelize(monologue);
+		__monologue_unkernelize(monologue, "media silencing signalling event");
 	}
 	else {
 		G_STRUCT_MEMBER(bool, call, call_offset) = on_off;
@@ -3039,7 +3039,7 @@ static const char *call_block_silence_media(bencode_item_t *input, bool on_off,
 		}
 		else
 			ilog(LOG_INFO, "%s media (entire call)", ucase_verb);
-		__call_unkernelize(call);
+		__call_unkernelize(call, "media silencing signalling event");
 	}
 
 	return NULL;

daemon/codec.c

@@ -4007,7 +4007,7 @@ void codec_update_all_handlers(struct call_monologue *ml) {
 		}
 	}
 
-	dialogue_unkernelize(ml);
+	dialogue_unkernelize(ml, "updating codec handlers");
 }
 void codec_update_all_source_handlers(struct call_monologue *ml, const struct sdp_ng_flags *flags) {
 	for (GList *l = ml->subscriptions.head; l; l = l->next) {
@@ -4027,7 +4027,7 @@ void codec_update_all_source_handlers(struct call_monologue *ml, const struct sd
 		}
 	}
 
-	dialogue_unkernelize(ml);
+	dialogue_unkernelize(ml, "updating codec source handlers");
 }
 
 

daemon/ice.c

@@ -1271,7 +1271,7 @@ static int __check_valid(struct ice_agent *ag) {
 		}
 	}
 
-	call_media_unkernelize(media);
+	call_media_unkernelize(media, "ICE negotiation event");
 
 	g_queue_clear(&all_compos);
 	return 1;

daemon/media_socket.c

@@ -67,7 +67,7 @@ struct packet_handler_ctx {
 
 	// verdicts:
 	bool update; // true if Redis info needs to be updated
-	bool unkernelize; // true if stream ought to be removed from kernel
+	const char *unkernelize; // non-null if stream ought to be removed from kernel
 	bool unconfirm; // forget learned peer address
 	bool unkernelize_subscriptions; // if our peer address changed
 	bool kernelize; // true if stream can be kernelized
@@ -1747,7 +1747,7 @@ static void __stream_update_stats(struct packet_stream *ps, bool have_in_lock) {
 
 
 /* must be called with in_lock held or call->master_lock held in W */
-void __unkernelize(struct packet_stream *p) {
+void __unkernelize(struct packet_stream *p, const char *reason) {
 	struct re_address rea;
 
 	reset_ps_kernel_stats(p);
@@ -1759,8 +1759,9 @@ void __unkernelize(struct packet_stream *p) {
 		return;
 
 	if (kernel.is_open && !PS_ISSET(p, NO_KERNEL_SUPPORT)) {
-		ilog(LOG_INFO, "Removing media stream from kernel: local %s",
-				endpoint_print_buf(&p->selected_sfd->socket.local));
+		ilog(LOG_INFO, "Removing media stream from kernel: local %s (%s)",
+				endpoint_print_buf(&p->selected_sfd->socket.local),
+				reason);
 		__stream_update_stats(p, true);
 		__re_address_translate_ep(&rea, &p->selected_sfd->socket.local);
 		kernel_del_stream(&rea);
@@ -1781,34 +1782,35 @@ void __reset_sink_handlers(struct packet_stream *ps) {
 		sh->handler = NULL;
 	}
 }
-void __stream_unconfirm(struct packet_stream *ps) {
-	__unkernelize(ps);
+void __stream_unconfirm(struct packet_stream *ps, const char *reason) {
+	__unkernelize(ps, reason);
 	if (!MEDIA_ISSET(ps->media, ASYMMETRIC)) {
 		if (ps->selected_sfd)
-			ilog(LOG_DEBUG | LOG_FLAG_LIMIT, "Unconfirming peer address for local %s",
-					endpoint_print_buf(&ps->selected_sfd->socket.local));
+			ilog(LOG_DEBUG | LOG_FLAG_LIMIT, "Unconfirming peer address for local %s (%s)",
+					endpoint_print_buf(&ps->selected_sfd->socket.local),
+					reason);
 		PS_CLEAR(ps, CONFIRMED);
 	}
 	__reset_sink_handlers(ps);
 }
-static void stream_unconfirm(struct packet_stream *ps) {
+static void stream_unconfirm(struct packet_stream *ps, const char *reason) {
 	if (!ps)
 		return;
 	mutex_lock(&ps->in_lock);
-	__stream_unconfirm(ps);
+	__stream_unconfirm(ps, reason);
 	mutex_unlock(&ps->in_lock);
 }
-static void unconfirm_sinks(GQueue *q) {
+static void unconfirm_sinks(GQueue *q, const char *reason) {
 	for (GList *l = q->head; l; l = l->next) {
 		struct sink_handler *sh = l->data;
-		stream_unconfirm(sh->sink);
+		stream_unconfirm(sh->sink, reason);
 	}
 }
-void unkernelize(struct packet_stream *ps) {
+void unkernelize(struct packet_stream *ps, const char *reason) {
 	if (!ps)
 		return;
 	mutex_lock(&ps->in_lock);
-	__unkernelize(ps);
+	__unkernelize(ps, reason);
 	mutex_unlock(&ps->in_lock);
 }
 
@@ -1921,12 +1923,13 @@ noop:
 }
 
 
-static bool __stream_ssrc_inout(struct packet_stream *ps, uint32_t ssrc, mutex_t *lock,
+// returns non-null with reason string if stream should be removed from kernel
+static const char *__stream_ssrc_inout(struct packet_stream *ps, uint32_t ssrc, mutex_t *lock,
 		struct ssrc_ctx *list[RTPE_NUM_SSRC_TRACKING], unsigned int *ctx_idx_p,
 		uint32_t output_ssrc,
 		struct ssrc_ctx **output, struct ssrc_hash *ssrc_hash, enum ssrc_dir dir, const char *label)
 {
-	int changed = false;
+	const char *ret = NULL;
 
 	mutex_lock(lock);
 
@@ -1943,7 +1946,7 @@ static bool __stream_ssrc_inout(struct packet_stream *ps, uint32_t ssrc, mutex_t
 		list[ctx_idx] =
 			get_ssrc_ctx(ssrc, ssrc_hash, dir, ps->media->monologue);
 
-		changed = true;
+		ret = "SSRC changed";
 		ilog(LOG_DEBUG, "New %s SSRC for: %s%s:%d SSRC: %x%s", label,
                         FMT_M(sockaddr_print_buf(&ps->endpoint.address), ps->endpoint.port, ssrc));
 	}
@@ -1970,17 +1973,19 @@ static bool __stream_ssrc_inout(struct packet_stream *ps, uint32_t ssrc, mutex_t
 	}
 
 	mutex_unlock(lock);
-	return changed;
+	return ret;
 }
 // check and update input SSRC pointers
-static bool __stream_ssrc_in(struct packet_stream *in_srtp, uint32_t ssrc_bs,
+// returns non-null with reason string if stream should be removed from kernel
+static const char *__stream_ssrc_in(struct packet_stream *in_srtp, uint32_t ssrc_bs,
 		struct ssrc_ctx **ssrc_in_p, struct ssrc_hash *ssrc_hash)
 {
 	return __stream_ssrc_inout(in_srtp, ntohl(ssrc_bs), &in_srtp->in_lock, in_srtp->ssrc_in,
 			&in_srtp->ssrc_in_idx, 0, ssrc_in_p, ssrc_hash, SSRC_DIR_INPUT, "ingress");
 }
 // check and update output SSRC pointers
-static bool __stream_ssrc_out(struct packet_stream *out_srtp, uint32_t ssrc_bs,
+// returns non-null with reason string if stream should be removed from kernel
+static const char *__stream_ssrc_out(struct packet_stream *out_srtp, uint32_t ssrc_bs,
 		struct ssrc_ctx *ssrc_in, struct ssrc_ctx **ssrc_out_p, struct ssrc_hash *ssrc_hash,
 		bool ssrc_change)
 {
@@ -2111,7 +2116,7 @@ static void media_packet_rtp_in(struct packet_handler_ctx *phc)
 	if (G_UNLIKELY(!proto_is_rtp(phc->mp.media->protocol)))
 		return;
 
-	bool unkern = false;
+	const char *unkern = NULL;
 
 	if (G_LIKELY(!phc->rtcp && !rtp_payload(&phc->mp.rtp, &phc->mp.payload, &phc->s))) {
 		unkern = __stream_ssrc_in(phc->in_srtp, phc->mp.rtp->ssrc, &phc->mp.ssrc_in,
@@ -2149,14 +2154,14 @@ static void media_packet_rtp_in(struct packet_handler_ctx *phc)
 	}
 
 	if (unkern)
-		phc->unkernelize = true;
+		phc->unkernelize = unkern;
 }
 static void media_packet_rtp_out(struct packet_handler_ctx *phc, struct sink_handler *sh)
 {
 	if (G_UNLIKELY(!proto_is_rtp(phc->mp.media->protocol)))
 		return;
 
-	bool unkern = 0;
+	const char *unkern = NULL;
 
 	if (G_LIKELY(!phc->rtcp && phc->mp.rtp)) {
 		unkern = __stream_ssrc_out(phc->out_srtp, phc->mp.rtp->ssrc, phc->mp.ssrc_in,
@@ -2170,7 +2175,7 @@ static void media_packet_rtp_out(struct packet_handler_ctx *phc, struct sink_han
 	}
 
 	if (unkern)
-		phc->unkernelize = true;
+		phc->unkernelize = unkern;
 }
 
 
@@ -2319,7 +2324,7 @@ static int media_packet_address_check(struct packet_handler_ctx *phc)
 				/* out_lock remains locked */
 				ilog(LOG_INFO | LOG_FLAG_LIMIT, "Peer address changed to %s%s%s",
 						FMT_M(endpoint_print_buf(&phc->mp.fsin)));
-				phc->unkernelize = true;
+				phc->unkernelize = "peer address changed (media handover)";
 				phc->unconfirm = true;
 				phc->update = true;
 				*ps_endpoint = phc->mp.fsin;
@@ -2413,7 +2418,7 @@ update_peerinfo:
 			ilog(LOG_DEBUG | LOG_FLAG_LIMIT, "Peer address changed from %s%s%s to %s%s%s",
 					FMT_M(endpoint_print_buf(&endpoint)),
 					FMT_M(endpoint_print_buf(use_endpoint_confirm)));
-			phc->unkernelize = true;
+			phc->unkernelize = "peer address changed";
 			phc->update = true;
 			phc->unkernelize_subscriptions = true;
 		}
@@ -2436,7 +2441,7 @@ update_addr:
 					endpoint_print_buf(&phc->mp.stream->selected_sfd->socket.local),
 					endpoint_print_buf(&phc->mp.sfd->socket.local));
 			phc->mp.stream->selected_sfd = phc->mp.sfd;
-			phc->unkernelize = true;
+			phc->unkernelize = "local socket switched";
 			phc->update = true;
 			phc->unkernelize_subscriptions = true;
 		}
@@ -2886,7 +2891,7 @@ next:
 	///////////////// INGRESS POST-PROCESSING HANDLING
 
 	if (phc->unkernelize) // for RTCP packet index updates
-		unkernelize(phc->mp.stream);
+		unkernelize(phc->mp.stream, phc->unkernelize);
 	if (phc->kernelize)
 		media_packet_kernel_check(phc);
 
@@ -2896,9 +2901,9 @@ drop:
 
 out:
 	if (phc->unconfirm) {
-		stream_unconfirm(phc->mp.stream);
-		unconfirm_sinks(&phc->mp.stream->rtp_sinks);
-		unconfirm_sinks(&phc->mp.stream->rtcp_sinks);
+		stream_unconfirm(phc->mp.stream, "peer address unconfirmed");
+		unconfirm_sinks(&phc->mp.stream->rtp_sinks, "peer address unconfirmed");
+		unconfirm_sinks(&phc->mp.stream->rtcp_sinks, "peer address unconfirmed");
 	}
 	if (phc->unkernelize_subscriptions) {
 		// XXX optimise this triple loop?
@@ -2911,7 +2916,7 @@ out:
 					continue;
 				for (GList *m = sub_media->streams.head; m; m = m->next) {
 					struct packet_stream *sub_ps = m->data;
-					__unkernelize(sub_ps);
+					__unkernelize(sub_ps, "subscriptions modified");
 				}
 			}
 		}

daemon/recording.c

@@ -371,7 +371,7 @@ void recording_start(struct call *call, const char *prefix, str *output_dest) {
 	for (l = call->streams.head; l; l = l->next) {
 		struct packet_stream *ps = l->data;
 		recording_setup_stream(ps);
-		__unkernelize(ps);
+		__unkernelize(ps, "recording start");
 		__reset_sink_handlers(ps);
 	}
 
@@ -703,7 +703,7 @@ void recording_finish(struct call *call) {
 	if (!call || !call->recording)
 		return;
 
-	__call_unkernelize(call);
+	__call_unkernelize(call, "recording finished");
 
 	struct recording *recording = call->recording;
 

include/call.h

@@ -741,9 +741,9 @@ struct call_media *call_media_new(struct call *call);
 void call_media_free(struct call_media **mdp);
 enum call_stream_state call_stream_state_machine(struct packet_stream *);
 void call_media_state_machine(struct call_media *m);
-void call_media_unkernelize(struct call_media *media);
-void dialogue_unkernelize(struct call_monologue *ml);
-void __monologue_unkernelize(struct call_monologue *monologue);
+void call_media_unkernelize(struct call_media *media, const char *);
+void dialogue_unkernelize(struct call_monologue *ml, const char *);
+void __monologue_unkernelize(struct call_monologue *monologue, const char *);
 void update_init_subscribers(struct call_monologue *ml, enum call_opmode opmode);
 
 int call_stream_address46(char *o, struct packet_stream *ps, enum stream_address_format format,
@@ -810,10 +810,10 @@ INLINE str *call_str_init_dup(struct call *c, char *s) {
 	str_init(&t, s);
 	return call_str_dup(c, &t);
 }
-INLINE void __call_unkernelize(struct call *call) {
+INLINE void __call_unkernelize(struct call *call, const char *reason) {
 	for (GList *l = call->monologues.head; l; l = l->next) {
 		struct call_monologue *ml = l->data;
-		__monologue_unkernelize(ml);
+		__monologue_unkernelize(ml, reason);
 	}
 }
 INLINE endpoint_t *packet_stream_local_addr(struct packet_stream *ps) {

include/media_socket.h

@@ -310,9 +310,9 @@ INLINE int open_intf_socket(socket_t *r, unsigned int port, const struct local_i
 }
 
 void kernelize(struct packet_stream *);
-void __unkernelize(struct packet_stream *);
-void unkernelize(struct packet_stream *);
-void __stream_unconfirm(struct packet_stream *);
+void __unkernelize(struct packet_stream *, const char *);
+void unkernelize(struct packet_stream *, const char *);
+void __stream_unconfirm(struct packet_stream *, const char *);
 void __reset_sink_handlers(struct packet_stream *);
 
 void media_update_stats(struct call_media *m);