<p>George Joseph has uploaded this change for <strong>review</strong>.</p><p><a href="https://gerrit.asterisk.org/c/asterisk/+/14892">View Change</a></p><pre style="font-family: monospace,monospace; white-space: pre-wrap;">debugging:  Add enough to choke a mule<br><br>Added to:<br> * bridges/bridge_softmix.c<br> * channels/chan_pjsip.c<br> * include/asterisk/res_pjsip_session.h<br> * main/channel.c<br> * res/res_pjsip_session.c<br><br>There NO functional changes in this commit.<br><br>Change-Id: I06af034d1ff3ea1feb56596fd7bd6d7939dfdcc3<br>---<br>M bridges/bridge_softmix.c<br>M channels/chan_pjsip.c<br>M include/asterisk/res_pjsip_session.h<br>M main/channel.c<br>M res/res_pjsip_session.c<br>5 files changed, 413 insertions(+), 277 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;">git pull ssh://gerrit.asterisk.org:29418/asterisk refs/changes/92/14892/1</pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/bridges/bridge_softmix.c b/bridges/bridge_softmix.c</span><br><span>index 931cf62..8d2d67c 100644</span><br><span>--- a/bridges/bridge_softmix.c</span><br><span>+++ b/bridges/bridge_softmix.c</span><br><span>@@ -629,6 +629,7 @@</span><br><span> </span><br><span>     joiner_video = ast_stream_topology_alloc();</span><br><span>  if (!joiner_video) {</span><br><span style="color: hsl(120, 100%, 40%);">+          ast_log(LOG_ERROR, "%s: Couldn't alloc topology\n", ast_channel_name(joiner->chan));</span><br><span>                return;</span><br><span>      }</span><br><span> </span><br><span>@@ -642,6 +643,7 @@</span><br><span>  ast_channel_unlock(joiner->chan);</span><br><span> </span><br><span>     if (res || !sc->topology) {</span><br><span style="color: hsl(120, 100%, 40%);">+                ast_log(LOG_ERROR, "%s: Couldn't append source streams\n", ast_channel_name(joiner->chan));</span><br><span>                 goto cleanup;</span><br><span>        }</span><br><span> </span><br><span>@@ -655,11 +657,17 @@</span><br><span>                        ast_channel_get_stream_topology(participant->chan));</span><br><span>              ast_channel_unlock(participant->chan);</span><br><span>            if (res) {</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_log(LOG_ERROR, "%s/%s: Couldn't append source streams\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                           ast_channel_name(participant->chan), ast_channel_name(joiner->chan));</span><br><span>                  goto cleanup;</span><br><span>                }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   ast_channel_request_stream_topology_change(joiner->chan, sc->topology, NULL);</span><br><span style="color: hsl(120, 100%, 40%);">+   res = ast_channel_request_stream_topology_change(joiner->chan, sc->topology, NULL);</span><br><span style="color: hsl(120, 100%, 40%);">+     if (res) {</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_debug(3, "%s: Couldn't request topology change\n", ast_channel_name(joiner->chan));</span><br><span style="color: hsl(120, 100%, 40%);">+              goto cleanup;</span><br><span style="color: hsl(120, 100%, 40%);">+ }</span><br><span> </span><br><span>        AST_LIST_TRAVERSE(participants, participant, entry) {</span><br><span>                if (participant == joiner) {</span><br><span>@@ -668,9 +676,16 @@</span><br><span> </span><br><span>              sc = participant->tech_pvt;</span><br><span>               if (append_all_streams(sc->topology, joiner_video)) {</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_log(LOG_ERROR, "%s/%s: Couldn't apopend streams\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_channel_name(participant->chan), ast_channel_name(joiner->chan));</span><br><span>                  goto cleanup;</span><br><span>                }</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);</span><br><span style="color: hsl(120, 100%, 40%);">+              res = ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);</span><br><span style="color: hsl(120, 100%, 40%);">+                if (res) {</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_debug(3, "%s/%s: Couldn't request topology change\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_channel_name(participant->chan), ast_channel_name(joiner->chan));</span><br><span style="color: hsl(120, 100%, 40%);">+                   goto cleanup;</span><br><span style="color: hsl(120, 100%, 40%);">+         }</span><br><span>    }</span><br><span> </span><br><span> cleanup:</span><br><span>@@ -2250,10 +2265,13 @@</span><br><span>  struct ast_stream_topology *added_streams;</span><br><span>   struct ast_bridge_channels_list *participants = &bridge->channels;</span><br><span>    struct ast_bridge_channel *participant;</span><br><span style="color: hsl(120, 100%, 40%);">+       SCOPE_ENTER(3, "%s: OT: %s NT: %s\n", ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_str_tmp(256, ast_stream_topology_to_str(old_topology, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_str_tmp(256, ast_stream_topology_to_str(new_topology, &STR_TMP)));</span><br><span> </span><br><span>       added_streams = ast_stream_topology_alloc();</span><br><span>         if (!added_streams) {</span><br><span style="color: hsl(0, 100%, 40%);">-           return;</span><br><span style="color: hsl(120, 100%, 40%);">+               SCOPE_EXIT_LOG(LOG_ERROR, "%s: Couldn't alloc topology\n", ast_channel_name(bridge_channel->chan));</span><br><span>         }</span><br><span> </span><br><span>        /* We go through the old topology comparing it to the new topology to determine what streams</span><br><span>@@ -2262,19 +2280,24 @@</span><br><span>        * Added streams are copied into a topology and added to each other participant while for</span><br><span>     * removed streams we merely store their position and mark them as removed later.</span><br><span>     */</span><br><span style="color: hsl(120, 100%, 40%);">+   ast_trace(-1, "%s: Checking for state changes\n", ast_channel_name(bridge_channel->chan));</span><br><span>      for (index = 0; index < ast_stream_topology_get_count(sc->topology) && index < ast_stream_topology_get_count(new_topology); ++index) {</span><br><span>              struct ast_stream *old_stream = ast_stream_topology_get_stream(sc->topology, index);</span><br><span>              struct ast_stream *new_stream = ast_stream_topology_get_stream(new_topology, index);</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_ENTER(4, "%s:   Slot: %d  Old stream: %s  New stream: %s\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                      index, ast_str_tmp(256, ast_stream_to_str(old_stream, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_str_tmp(256, ast_stream_to_str(new_stream, &STR_TMP)));</span><br><span> </span><br><span>          /* Ignore all streams that don't carry video and streams that are strictly outgoing destination streams */</span><br><span>               if ((ast_stream_get_type(old_stream) != AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) != AST_MEDIA_TYPE_VIDEO) ||</span><br><span>                  !strncmp(ast_stream_get_name(new_stream), SOFTBRIDGE_VIDEO_DEST_PREFIX,</span><br><span>                              SOFTBRIDGE_VIDEO_DEST_LEN)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Stream %d ignored\n",  ast_channel_name(bridge_channel->chan), index);</span><br><span>           }</span><br><span> </span><br><span>                if (ast_stream_get_type(old_stream) == AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) != AST_MEDIA_TYPE_VIDEO) {</span><br><span>                    /* If a stream renegotiates from video to non-video then we need to remove it as a source */</span><br><span style="color: hsl(120, 100%, 40%);">+                  ast_trace(-1, "%s: Stream %d added to remove list\n",  ast_channel_name(bridge_channel->chan), index);</span><br><span>                  removed_streams[removed_streams_count++] = index;</span><br><span>            } else if (ast_stream_get_type(old_stream) != AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) == AST_MEDIA_TYPE_VIDEO) {</span><br><span>                     if (ast_stream_get_state(new_stream) != AST_STREAM_STATE_REMOVED) {</span><br><span>@@ -2282,11 +2305,14 @@</span><br><span>                                if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),</span><br><span>                                                   bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,</span><br><span>                                                    new_stream, index)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                   goto cleanup;</span><br><span style="color: hsl(120, 100%, 40%);">+                                 SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append source stream %d:%s\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                                          index, ast_stream_get_name(new_stream));</span><br><span>                             }</span><br><span style="color: hsl(120, 100%, 40%);">+                             ast_trace(-1, "%s: Stream %d changed from non-video to video\n",  ast_channel_name(bridge_channel->chan), index);</span><br><span>                       }</span><br><span>            } else if (ast_stream_get_state(old_stream) != AST_STREAM_STATE_REMOVED &&</span><br><span>                           ast_stream_get_state(new_stream) != AST_STREAM_STATE_SENDRECV && ast_stream_get_state(new_stream) != AST_STREAM_STATE_RECVONLY) {</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Stream %d added to remove list\n",  ast_channel_name(bridge_channel->chan), index);</span><br><span>                  /* If a stream renegotiates and is removed then we remove it */</span><br><span>                      removed_streams[removed_streams_count++] = index;</span><br><span>            } else if ((ast_stream_get_state(old_stream) == AST_STREAM_STATE_REMOVED || ast_stream_get_state(old_stream) == AST_STREAM_STATE_INACTIVE ||</span><br><span>@@ -2297,9 +2323,14 @@</span><br><span>                        if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),</span><br><span>                                           bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,</span><br><span>                                            new_stream, index)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                           goto cleanup;</span><br><span style="color: hsl(120, 100%, 40%);">+                         SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append source stream %d:%s\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                                  index, ast_stream_get_name(new_stream));</span><br><span>                     }</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Stream %d:%s changed state from %s to %s\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                         index, ast_stream_get_name(old_stream), ast_stream_state2str(ast_stream_get_state(old_stream)),</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_stream_state2str(ast_stream_get_state(new_stream)));</span><br><span>             }</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT();</span><br><span>        }</span><br><span> </span><br><span>        /* Any newly added streams that did not take the position of a removed stream</span><br><span>@@ -2307,18 +2338,26 @@</span><br><span>       * removed from the topology but merely marked as removed we can pick up where we</span><br><span>     * left off when comparing the old and new topologies.</span><br><span>        */</span><br><span style="color: hsl(120, 100%, 40%);">+   ast_trace(-1, "%s: Checking for newly added streams\n", ast_channel_name(bridge_channel->chan));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>      for (; index < ast_stream_topology_get_count(new_topology); ++index) {</span><br><span>            struct ast_stream *stream = ast_stream_topology_get_stream(new_topology, index);</span><br><span style="color: hsl(120, 100%, 40%);">+              SCOPE_ENTER(4, "%s: Checking stream %d:%s\n",  ast_channel_name(bridge_channel->chan), index,</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_stream_get_name(stream));</span><br><span> </span><br><span>            if (!is_video_source(stream)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                 continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Stream %d:%s is not video source\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                             index, ast_stream_get_name(stream));</span><br><span>                 }</span><br><span> </span><br><span>                if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),</span><br><span>                                   bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,</span><br><span>                                    stream, index)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                       goto cleanup;</span><br><span style="color: hsl(120, 100%, 40%);">+                 SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append stream %d:%s\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                         index, ast_stream_get_name(stream));</span><br><span>                 }</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT("%s:   Added new stream %s\n", ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_str_tmp(256, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>  }</span><br><span> </span><br><span>        /*  We always update the stored topology if we can to reflect what is currently negotiated */</span><br><span>@@ -2333,42 +2372,67 @@</span><br><span>       * other participants.</span><br><span>        */</span><br><span>  if (!removed_streams_count && !ast_stream_topology_get_count(added_streams)) {</span><br><span style="color: hsl(120, 100%, 40%);">+                ast_trace(-1, "%s: Nothing added or removed\n", ast_channel_name(bridge_channel->chan));</span><br><span>                goto cleanup;</span><br><span>        }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ ast_trace(-1, "%s: Processing adds and removes\n", ast_channel_name(bridge_channel->chan));</span><br><span>     /* Go through each participant adding in the new streams and removing the old ones */</span><br><span style="color: hsl(0, 100%, 40%);">-   AST_LIST_TRAVERSE(participants, participant, entry) {</span><br><span style="color: hsl(0, 100%, 40%);">-           if (participant == bridge_channel) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    continue;</span><br><span style="color: hsl(0, 100%, 40%);">-               }</span><br><span style="color: hsl(120, 100%, 40%);">+     AST_LIST_TRAVERSE(participants, participant, entry)</span><br><span style="color: hsl(120, 100%, 40%);">+   {</span><br><span style="color: hsl(120, 100%, 40%);">+             struct softmix_channel *participant_sc = participant->tech_pvt;</span><br><span style="color: hsl(120, 100%, 40%);">+            SCOPE_ENTER(4, "%s/%s: Old participant topology %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_channel_name(participant->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_str_tmp(256, ast_stream_topology_to_str(participant_sc->topology, &STR_TMP)));</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-           sc = participant->tech_pvt;</span><br><span style="color: hsl(120, 100%, 40%);">+                if (participant == bridge_channel) {</span><br><span style="color: hsl(120, 100%, 40%);">+                  SCOPE_EXIT_EXPR(continue, "%s/%s: Same channel.  Skipping\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                            ast_channel_name(participant->chan));</span><br><span style="color: hsl(120, 100%, 40%);">+              }</span><br><span> </span><br><span>                /* We add in all the new streams first so that they do not take the place</span><br><span>             * of any of our removed streams, allowing the remote side to reset the state</span><br><span>                 * for each removed stream. */</span><br><span style="color: hsl(0, 100%, 40%);">-                if (append_all_streams(sc->topology, added_streams)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                        goto cleanup;</span><br><span style="color: hsl(0, 100%, 40%);">-                }</span><br><span style="color: hsl(120, 100%, 40%);">+         if (append_all_streams(participant_sc->topology, added_streams)) {</span><br><span style="color: hsl(120, 100%, 40%);">+                 SCOPE_EXIT_EXPR(goto cleanup, "%s/%s: Couldn't append streams\n",  ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                           ast_channel_name(participant->chan));</span><br><span style="color: hsl(120, 100%, 40%);">+              }</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_trace(-1, "%s/%s:   Adding streams %s\n", ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_channel_name(participant->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_str_tmp(256, ast_stream_topology_to_str(added_streams, &STR_TMP)));</span><br><span> </span><br><span>              /* Then we go through and remove any ones that were removed */</span><br><span style="color: hsl(0, 100%, 40%);">-          for (index = 0; removed_streams_count && index < ast_stream_topology_get_count(sc->topology); ++index) {</span><br><span style="color: hsl(120, 100%, 40%);">+                for (index = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+                       removed_streams_count && index < ast_stream_topology_get_count(sc->topology); ++index) {</span><br><span>                       struct ast_stream *stream = ast_stream_topology_get_stream(sc->topology, index);</span><br><span>                  int removed_stream;</span><br><span> </span><br><span>                      for (removed_stream = 0; removed_stream < removed_streams_count; ++removed_stream) {</span><br><span style="color: hsl(0, 100%, 40%);">-                         if (is_video_dest(stream, ast_channel_name(bridge_channel->chan), removed_streams[removed_stream])) {</span><br><span style="color: hsl(120, 100%, 40%);">+                              if (is_video_dest(stream, ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                                  removed_streams[removed_stream])) {</span><br><span style="color: hsl(120, 100%, 40%);">+                                   ast_trace(-1, "%s/%s:    Removing stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                             ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                                            ast_channel_name(participant->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                                               ast_str_tmp(256, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>                                  ast_stream_set_state(stream, AST_STREAM_STATE_REMOVED);</span><br><span>                              }</span><br><span>                    }</span><br><span>            }</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_channel_request_stream_topology_change(participant->chan, participant_sc->topology, NULL);</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT("%s/%s:   New participant topology %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_channel_name(participant->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_str_tmp(256, ast_stream_topology_to_str(participant_sc->topology, &STR_TMP)));</span><br><span style="color: hsl(120, 100%, 40%);">+     }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-                ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);</span><br><span style="color: hsl(0, 100%, 40%);">-        }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(120, 100%, 40%);">+        ast_trace(-1, "%s: New topology %s\n", ast_channel_name(bridge_channel->chan),</span><br><span style="color: hsl(120, 100%, 40%);">+           ast_str_tmp(256, ast_stream_topology_to_str(sc->topology, &STR_TMP)));</span><br><span> </span><br><span> cleanup:</span><br><span>        ast_stream_topology_free(added_streams);</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_EXIT();</span><br><span> }</span><br><span> </span><br><span> /*!</span><br><span>@@ -2389,6 +2453,7 @@</span><br><span>        struct ast_vector_int media_types;</span><br><span>   int nths[AST_MEDIA_TYPE_END] = {0};</span><br><span>  int idx;</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_ENTER(3, "%s: \n", ast_channel_name(bridge_channel->chan));</span><br><span> </span><br><span>   switch (bridge->softmix.video_mode.mode) {</span><br><span>        case AST_BRIDGE_VIDEO_MODE_NONE:</span><br><span>@@ -2396,7 +2461,7 @@</span><br><span>     case AST_BRIDGE_VIDEO_MODE_TALKER_SRC:</span><br><span>       default:</span><br><span>             ast_bridge_channel_stream_map(bridge_channel);</span><br><span style="color: hsl(0, 100%, 40%);">-          return;</span><br><span style="color: hsl(120, 100%, 40%);">+               SCOPE_EXIT_RTN("%s: Not in SFU mode\n", ast_channel_name(bridge_channel->chan));</span><br><span>        case AST_BRIDGE_VIDEO_MODE_SFU:</span><br><span>              break;</span><br><span>       }</span><br><span>@@ -2506,6 +2571,7 @@</span><br><span>    }</span><br><span> </span><br><span>        AST_VECTOR_FREE(&media_types);</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_EXIT_RTN("%s\n", ast_channel_name(bridge_channel->chan));</span><br><span> }</span><br><span> </span><br><span> static struct ast_bridge_technology softmix_bridge = {</span><br><span>diff --git a/channels/chan_pjsip.c b/channels/chan_pjsip.c</span><br><span>index e99ec31..93889fc 100644</span><br><span>--- a/channels/chan_pjsip.c</span><br><span>+++ b/channels/chan_pjsip.c</span><br><span>@@ -1585,8 +1585,11 @@</span><br><span> </span><br><span> static int on_topology_change_response(struct ast_sip_session *session, pjsip_rx_data *rdata)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-     SCOPE_ENTER(1, "%s Status code: %d\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-             rdata->msg_info.msg->line.status.code);</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_ENTER(3, "%s: Received response code %d.  PT: %s  AT: %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+               rdata->msg_info.msg->line.status.code,</span><br><span style="color: hsl(120, 100%, 40%);">+          ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_str_tmp(256, ast_stream_topology_to_str(session->active_media_state->topology, &STR_TMP)));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> </span><br><span>      if (PJSIP_IS_STATUS_IN_CLASS(rdata->msg_info.msg->line.status.code, 200)) {</span><br><span>            /* The topology was changed to something new so give notice to what requested</span><br><span>@@ -1594,27 +1597,33 @@</span><br><span>               */</span><br><span>          if (session->channel) {</span><br><span>                   ast_queue_control(session->channel, AST_CONTROL_STREAM_TOPOLOGY_CHANGED);</span><br><span style="color: hsl(120, 100%, 40%);">+                  SCOPE_EXIT_RTN_VALUE(0, "%s: Queued topology change frame\n", ast_sip_session_get_name(session));</span><br><span>          }</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT_RTN_VALUE(0, "%s: No channel?  Can't queue topology change frame\n", ast_sip_session_get_name(session));</span><br><span>    } else if (300 <= rdata->msg_info.msg->line.status.code) {</span><br><span>          /* The topology change failed, so drop the current pending media state */</span><br><span>            ast_sip_session_media_state_reset(session->pending_media_state);</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_RTN_VALUE(0, "%s: response code > 300.  Resetting pending media state\n", ast_sip_session_get_name(session));</span><br><span>        }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN_VALUE(0);</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_EXIT_RTN_VALUE(0, "%s: Nothing to do\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int send_topology_change_refresh(void *data)</span><br><span> {</span><br><span>    struct topology_change_refresh_data *refresh_data = data;</span><br><span style="color: hsl(120, 100%, 40%);">+     struct ast_sip_session *session = refresh_data->session;</span><br><span>  int ret;</span><br><span style="color: hsl(0, 100%, 40%);">-        SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(refresh_data->session));</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_ENTER(3, "%s: %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+               ast_str_tmp(256, ast_stream_topology_to_str(refresh_data->media_state->topology, &STR_TMP)));</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-     ret = ast_sip_session_refresh(refresh_data->session, NULL, NULL, on_topology_change_response,</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+    ret = ast_sip_session_refresh(session, NULL, NULL, on_topology_change_response,</span><br><span>              AST_SIP_SESSION_REFRESH_METHOD_INVITE, 1, refresh_data->media_state);</span><br><span>     refresh_data->media_state = NULL;</span><br><span>         topology_change_refresh_data_free(refresh_data);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-    SCOPE_EXIT_RTN_VALUE(ret, "RC: %d\n", ret);</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_EXIT_RTN_VALUE(ret, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int handle_topology_request_change(struct ast_sip_session *session,</span><br><span>@@ -1647,10 +1656,15 @@</span><br><span>     size_t device_buf_size;</span><br><span>      int i;</span><br><span>       const struct ast_stream_topology *topology;</span><br><span style="color: hsl(0, 100%, 40%);">-     struct ast_frame f = { .frametype = AST_FRAME_CONTROL, .subclass = { .integer = condition } };</span><br><span style="color: hsl(0, 100%, 40%);">-  char subclass[40] = "";</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_ENTER(1, "%s Handling %s\n", ast_channel_name(ast),</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_frame_subclass2str(&f, subclass, sizeof(subclass), NULL, 0));</span><br><span style="color: hsl(120, 100%, 40%);">+ struct ast_frame f = {</span><br><span style="color: hsl(120, 100%, 40%);">+                .frametype = AST_FRAME_CONTROL,</span><br><span style="color: hsl(120, 100%, 40%);">+               .subclass = {</span><br><span style="color: hsl(120, 100%, 40%);">+                 .integer = condition</span><br><span style="color: hsl(120, 100%, 40%);">+          }</span><br><span style="color: hsl(120, 100%, 40%);">+     };</span><br><span style="color: hsl(120, 100%, 40%);">+    char condition_name[256];</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_ENTER(3, "%s: Indicated %s\n", ast_channel_name(ast),</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_frame_subclass2str(&f, condition_name, sizeof(condition_name), NULL, 0));</span><br><span> </span><br><span>        switch (condition) {</span><br><span>         case AST_CONTROL_RINGING:</span><br><span>@@ -1755,9 +1769,9 @@</span><br><span>            ao2_ref(channel->session, +1);</span><br><span> #ifdef HAVE_PJSIP_INV_SESSION_REF</span><br><span>               if (pjsip_inv_add_ref(channel->session->inv_session) != PJ_SUCCESS) {</span><br><span style="color: hsl(0, 100%, 40%);">-                     ast_log(LOG_ERROR, "Can't increase the session reference counter\n");</span><br><span>                  ao2_cleanup(channel->session);</span><br><span style="color: hsl(0, 100%, 40%);">-                       SCOPE_EXIT_RTN_VALUE(-1, "Couldn't increase the session reference counter\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                  SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't increase the session reference counter\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_channel_name(ast));</span><br><span>              }</span><br><span> #endif</span><br><span>          if (ast_sip_push_task(channel->session->serializer, update_connected_line_information, channel->session)) {</span><br><span>@@ -1847,6 +1861,8 @@</span><br><span>                 break;</span><br><span>       case AST_CONTROL_STREAM_TOPOLOGY_REQUEST_CHANGE:</span><br><span>             topology = data;</span><br><span style="color: hsl(120, 100%, 40%);">+              ast_trace(-1, "%s: New topology: %s\n", ast_channel_name(ast),</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));</span><br><span>               res = handle_topology_request_change(channel->session, topology);</span><br><span>                 break;</span><br><span>       case AST_CONTROL_STREAM_TOPOLOGY_CHANGED:</span><br><span>@@ -1866,18 +1882,17 @@</span><br><span>          struct indicate_data *ind_data = indicate_data_alloc(channel->session, condition, response_code, data, datalen);</span><br><span> </span><br><span>              if (!ind_data) {</span><br><span style="color: hsl(0, 100%, 40%);">-                        SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create indicate data\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                    SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc indicate data\n", ast_channel_name(ast));</span><br><span>          }</span><br><span> #ifdef HAVE_PJSIP_INV_SESSION_REF</span><br><span>               if (pjsip_inv_add_ref(ind_data->session->inv_session) != PJ_SUCCESS) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_log(LOG_ERROR, "Can't increase the session reference counter\n");</span><br><span>                  ao2_cleanup(ind_data);</span><br><span style="color: hsl(0, 100%, 40%);">-                  SCOPE_EXIT_RTN_VALUE(-1, "Couldn't increase the session reference counter\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                  SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't increase the session reference counter\n", ast_channel_name(ast));</span><br><span>               }</span><br><span> #endif</span><br><span>          if (ast_sip_push_task(channel->session->serializer, indicate, ind_data)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                        ast_log(LOG_NOTICE, "Cannot send response code %d to endpoint %s. Could not queue task properly\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                   response_code, ast_sorcery_object_get_id(channel->session->endpoint));</span><br><span style="color: hsl(120, 100%, 40%);">+                  ast_log(LOG_ERROR, "%s: Cannot send response code %d to endpoint %s. Could not queue task properly\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                      ast_channel_name(ast), response_code, ast_sorcery_object_get_id(channel->session->endpoint));</span><br><span> #ifdef HAVE_PJSIP_INV_SESSION_REF</span><br><span>                     pjsip_inv_dec_ref(ind_data->session->inv_session);</span><br><span> #endif</span><br><span>@@ -1886,7 +1901,7 @@</span><br><span>           }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN_VALUE(res, "RC: %d\n", res);</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_channel_name(ast));</span><br><span> }</span><br><span> </span><br><span> struct transfer_data {</span><br><span>@@ -3079,10 +3094,10 @@</span><br><span>     RAII_VAR(struct ast_datastore *, datastore, NULL, ao2_cleanup);</span><br><span>      struct transport_info_data *transport_data;</span><br><span>  pjsip_tx_data *packet = NULL;</span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+  SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (session->channel) {</span><br><span style="color: hsl(0, 100%, 40%);">-              SCOPE_EXIT_RTN_VALUE(0, "Already have channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_RTN_VALUE(0, "%s: No channel\n", ast_sip_session_get_name(session));</span><br><span>    }</span><br><span> </span><br><span>        /* Check for a to-tag to determine if this is a reinvite */</span><br><span>@@ -3098,17 +3113,17 @@</span><br><span>                 */</span><br><span>          session->defer_terminate = 0;</span><br><span>             ast_sip_session_terminate(session, 400);</span><br><span style="color: hsl(0, 100%, 40%);">-                SCOPE_EXIT_RTN_VALUE(-1, "Reinvite without channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT_RTN_VALUE(-1, "%s: We have a To tag but no channel.  Terminating session\n", ast_sip_session_get_name(session));</span><br><span>        }</span><br><span> </span><br><span>        datastore = ast_sip_session_alloc_datastore(&transport_info, "transport_info");</span><br><span>        if (!datastore) {</span><br><span style="color: hsl(0, 100%, 40%);">-               SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create datastore\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc transport_info datastore\n", ast_sip_session_get_name(session));</span><br><span>   }</span><br><span> </span><br><span>        transport_data = ast_calloc(1, sizeof(*transport_data));</span><br><span>     if (!transport_data) {</span><br><span style="color: hsl(0, 100%, 40%);">-          SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create transport_data\n");</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc transport_info\n", ast_sip_session_get_name(session));</span><br><span>     }</span><br><span>    pj_sockaddr_cp(&transport_data->local_addr, &rdata->tp_info.transport->local_addr);</span><br><span>         pj_sockaddr_cp(&transport_data->remote_addr, &rdata->pkt_info.src_addr);</span><br><span>@@ -3121,12 +3136,12 @@</span><br><span>                     ast_sip_session_send_response(session, packet);</span><br><span>              }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-           ast_log(LOG_ERROR, "Failed to allocate new PJSIP channel on incoming SIP INVITE\n");</span><br><span style="color: hsl(0, 100%, 40%);">-          SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Failed to allocate new PJSIP channel on incoming SIP INVITE\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_sip_session_get_name(session));</span><br><span>         }</span><br><span>    /* channel gets created on incoming request, but we wait to call start</span><br><span>            so other supplements have a chance to run */</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN_VALUE(0);</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int call_pickup_incoming_request(struct ast_sip_session *session, pjsip_rx_data *rdata)</span><br><span>@@ -3225,11 +3240,10 @@</span><br><span>   struct pjsip_status_line status = rdata->msg_info.msg->line.status;</span><br><span>    struct ast_control_pvt_cause_code *cause_code;</span><br><span>       int data_size = sizeof(*cause_code);</span><br><span style="color: hsl(0, 100%, 40%);">-    SCOPE_ENTER(1, "%s Method: %.*s Status: %d\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-             (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_ENTER(3, "%s: Status: %d\n", ast_sip_session_get_name(session), status.code);</span><br><span> </span><br><span>    if (!session->channel) {</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN("No channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT_RTN("%s: No channel\n", ast_sip_session_get_name(session));</span><br><span>     }</span><br><span> </span><br><span>        /* Build and send the tech-specific cause information */</span><br><span>@@ -3249,8 +3263,7 @@</span><br><span> </span><br><span>         switch (status.code) {</span><br><span>       case 180:</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_trace(1, "%s Method: %.*s Status: %d  Queueing RINGING\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                     (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_trace(-1, "%s: Queueing RINGING\n", ast_sip_session_get_name(session));</span><br><span>                ast_queue_control(session->channel, AST_CONTROL_RINGING);</span><br><span>                 ast_channel_lock(session->channel);</span><br><span>               if (ast_channel_state(session->channel) != AST_STATE_UP) {</span><br><span>@@ -3259,6 +3272,7 @@</span><br><span>                ast_channel_unlock(session->channel);</span><br><span>             break;</span><br><span>       case 183:</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_trace(-1, "%s: Queueing PROGRESS\n", ast_sip_session_get_name(session));</span><br><span>               if (session->endpoint->ignore_183_without_sdp) {</span><br><span>                       pjsip_rdata_sdp_info *sdp = pjsip_rdata_get_sdp_info(rdata);</span><br><span>                         if (sdp && sdp->body.ptr) {</span><br><span>@@ -3273,34 +3287,28 @@</span><br><span>             }</span><br><span>            break;</span><br><span>       case 200:</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_trace(1, "%s Method: %.*s Status: %d  Queueing ANSWER\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                      (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_trace(-1, "%s: Queueing ANSWER\n", ast_sip_session_get_name(session));</span><br><span>                 ast_queue_control(session->channel, AST_CONTROL_ANSWER);</span><br><span>          break;</span><br><span>       default:</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_trace(1, "%s Method: %.*s Status: %d  Ignored\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                      (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_trace(-1, "%s: Not queueing anything\n", ast_sip_session_get_name(session));</span><br><span>           break;</span><br><span>       }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT_RTN("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int chan_pjsip_incoming_ack(struct ast_sip_session *session, struct pjsip_rx_data *rdata)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-  SCOPE_ENTER(1, "%s Method: %.*s Status: %d  After Media\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr,</span><br><span style="color: hsl(0, 100%, 40%);">-         rdata->msg_info.msg->line.status.code);</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (rdata->msg_info.msg->line.req.method.id == PJSIP_ACK_METHOD) {</span><br><span>             if (session->endpoint->media.direct_media.enabled && session->channel) {</span><br><span style="color: hsl(0, 100%, 40%);">-                       ast_trace(1, "%s Method: %.*s  Queueing SRCCHANGE\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                              (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr);</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_trace(-1, "%s: Queueing SRCCHANGE\n", ast_sip_session_get_name(session));</span><br><span>                      ast_queue_control(session->channel, AST_CONTROL_SRCCHANGE);</span><br><span>               }</span><br><span>    }</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN_VALUE(0);</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int update_devstate(void *obj, void *arg, int flags)</span><br><span>diff --git a/include/asterisk/res_pjsip_session.h b/include/asterisk/res_pjsip_session.h</span><br><span>index 9db68a8..1e83696 100644</span><br><span>--- a/include/asterisk/res_pjsip_session.h</span><br><span>+++ b/include/asterisk/res_pjsip_session.h</span><br><span>@@ -121,6 +121,10 @@</span><br><span>    unsigned int changed;</span><br><span>        /*! \brief Remote media stream label */</span><br><span>      char *remote_mslabel;</span><br><span style="color: hsl(120, 100%, 40%);">+ /*! \brief Remote stream label */</span><br><span style="color: hsl(120, 100%, 40%);">+     char *remote_label;</span><br><span style="color: hsl(120, 100%, 40%);">+   /*! \brief Stream name */</span><br><span style="color: hsl(120, 100%, 40%);">+     char *stream_name;</span><br><span> };</span><br><span> </span><br><span> /*!</span><br><span>diff --git a/main/channel.c b/main/channel.c</span><br><span>index c26089a..276c1bc 100644</span><br><span>--- a/main/channel.c</span><br><span>+++ b/main/channel.c</span><br><span>@@ -11029,8 +11029,10 @@</span><br><span>  }</span><br><span> </span><br><span>        if (ast_stream_topology_equal(ast_channel_get_stream_topology(chan), topology)) {</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_debug(3, "Topology of %s already matches what is requested so ignoring topology change request\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_channel_name(chan));</span><br><span style="color: hsl(120, 100%, 40%);">+              ast_debug(2, "%s: Topologies already match. Current: %s  Requested: %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                          ast_channel_name(chan),</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_str_tmp(256, ast_stream_topology_to_str(ast_channel_get_stream_topology(chan), &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                            ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));</span><br><span>               ast_channel_unlock(chan);</span><br><span>            return 0;</span><br><span>    }</span><br><span>diff --git a/res/res_pjsip_session.c b/res/res_pjsip_session.c</span><br><span>index 0385a96..b93fa4e 100644</span><br><span>--- a/res/res_pjsip_session.c</span><br><span>+++ b/res/res_pjsip_session.c</span><br><span>@@ -483,12 +483,15 @@</span><br><span> </span><br><span>       ast_free(session_media->mid);</span><br><span>     ast_free(session_media->remote_mslabel);</span><br><span style="color: hsl(120, 100%, 40%);">+   ast_free(session_media->remote_label);</span><br><span style="color: hsl(120, 100%, 40%);">+     ast_free(session_media->stream_name);</span><br><span> }</span><br><span> </span><br><span> struct ast_sip_session_media *ast_sip_session_media_state_add(struct ast_sip_session *session,</span><br><span>  struct ast_sip_session_media_state *media_state, enum ast_media_type type, int position)</span><br><span> {</span><br><span>        struct ast_sip_session_media *session_media = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_ENTER(1, "%s Adding position %d\n", ast_sip_session_get_name(session), position);</span><br><span> </span><br><span>        /* It is possible for this media state to already contain a session for the stream. If this</span><br><span>   * is the case we simply return it.</span><br><span>@@ -496,7 +499,7 @@</span><br><span>    if (position < AST_VECTOR_SIZE(&media_state->sessions)) {</span><br><span>          session_media = AST_VECTOR_GET(&media_state->sessions, position);</span><br><span>             if (session_media) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    return session_media;</span><br><span style="color: hsl(120, 100%, 40%);">+                 SCOPE_EXIT_RTN_VALUE(session_media, "Using existing media_session\n");</span><br><span>             }</span><br><span>    }</span><br><span> </span><br><span>@@ -506,6 +509,7 @@</span><br><span>          /* A stream can never exist without an accompanying media session */</span><br><span>                 if (session_media->type == type) {</span><br><span>                        ao2_ref(session_media, +1);</span><br><span style="color: hsl(120, 100%, 40%);">+                   ast_trace(1, "Reusing existing media session\n");</span><br><span>                  /*</span><br><span>                    * If this session_media was previously removed, its bundle group was probably reset</span><br><span>                          * to -1 so if bundling is enabled on the endpoint, we need to reset it to 0, set</span><br><span>@@ -517,10 +521,12 @@</span><br><span>                            ast_free(session_media->mid);</span><br><span>                             if (ast_asprintf(&session_media->mid, "%s-%d", ast_codec_media_type2str(type), position) < 0) {</span><br><span>                                  ao2_ref(session_media, -1);</span><br><span style="color: hsl(0, 100%, 40%);">-                                     return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+                                  SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't alloc mid\n");</span><br><span>                            }</span><br><span>                    }</span><br><span>            } else {</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_trace(1, "Can't reuse existing media session because the types are different. %s <> %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                            ast_codec_media_type2str(type), ast_codec_media_type2str(session_media->type));</span><br><span>                   session_media = NULL;</span><br><span>                }</span><br><span>    }</span><br><span>@@ -531,6 +537,7 @@</span><br><span>              if (!session_media) {</span><br><span>                        return NULL;</span><br><span>                 }</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_trace(1, "Creating new media session\n");</span><br><span> </span><br><span>          session_media->encryption = session->endpoint->media.rtp.encryption;</span><br><span>                session_media->remote_ice = session->endpoint->media.rtp.ice_support;</span><br><span>@@ -546,7 +553,7 @@</span><br><span>                          */</span><br><span>                  if (ast_asprintf(&session_media->mid, "%s-%d", ast_codec_media_type2str(type), position) < 0) {</span><br><span>                          ao2_ref(session_media, -1);</span><br><span style="color: hsl(0, 100%, 40%);">-                             return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+                          SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't alloc mid\n");</span><br><span>                    }</span><br><span>                    session_media->bundle_group = 0;</span><br><span> </span><br><span>@@ -560,18 +567,23 @@</span><br><span>              }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ ast_free(session_media->stream_name);</span><br><span style="color: hsl(120, 100%, 40%);">+      session_media->stream_name = ast_strdup(ast_stream_get_name(ast_stream_topology_get_stream(media_state->topology, position)));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>       if (AST_VECTOR_REPLACE(&media_state->sessions, position, session_media)) {</span><br><span>            ao2_ref(session_media, -1);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-         return NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't replace media_session\n");</span><br><span>        }</span><br><span> </span><br><span>        /* If this stream will be active in some way and it is the first of this type then consider this the default media session to match */</span><br><span>       if (!media_state->default_session[type] && ast_stream_get_state(ast_stream_topology_get_stream(media_state->topology, position)) != AST_STREAM_STATE_REMOVED) {</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_trace(1, "Setting media session as default for %s\n", ast_codec_media_type2str(session_media->type));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>             media_state->default_session[type] = session_media;</span><br><span>       }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   return session_media;</span><br><span style="color: hsl(120, 100%, 40%);">+ SCOPE_EXIT_RTN_VALUE(session_media, "Done\n");</span><br><span> }</span><br><span> </span><br><span> static int is_stream_limitation_reached(enum ast_media_type type, const struct ast_sip_endpoint *endpoint, int *type_streams)</span><br><span>@@ -676,6 +688,8 @@</span><br><span> </span><br><span>         ast_free(session_media->remote_mslabel);</span><br><span>  session_media->remote_mslabel = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+      ast_free(session_media->remote_label);</span><br><span style="color: hsl(120, 100%, 40%);">+     session_media->remote_label = NULL;</span><br><span> </span><br><span>   for (index = 0; index < stream->attr_count; ++index) {</span><br><span>                 pjmedia_sdp_attr *attr = stream->attr[index];</span><br><span>@@ -684,8 +698,12 @@</span><br><span>              char *msid, *tmp = attr_value;</span><br><span>               static const pj_str_t STR_msid = { "msid", 4 };</span><br><span>            static const pj_str_t STR_ssrc = { "ssrc", 4 };</span><br><span style="color: hsl(120, 100%, 40%);">+             static const pj_str_t STR_label = { "label", 5 };</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-         if (!pj_strcmp(&attr->name, &STR_msid)) {</span><br><span style="color: hsl(120, 100%, 40%);">+          if (!pj_strcmp(&attr->name, &STR_label)) {</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_copy_pj_str(attr_value, &attr->value, sizeof(attr_value));</span><br><span style="color: hsl(120, 100%, 40%);">+                 session_media->remote_label = ast_strdup(attr_value);</span><br><span style="color: hsl(120, 100%, 40%);">+              } else if (!pj_strcmp(&attr->name, &STR_msid)) {</span><br><span>                  ast_copy_pj_str(attr_value, &attr->value, sizeof(attr_value));</span><br><span>                        msid = strsep(&tmp, " ");</span><br><span>                      session_media->remote_mslabel = ast_strdup(msid);</span><br><span>@@ -745,18 +763,19 @@</span><br><span>         int i;</span><br><span>       int handled = 0;</span><br><span>     int type_streams[AST_MEDIA_TYPE_END] = {0};</span><br><span style="color: hsl(0, 100%, 40%);">-     SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+  SCOPE_ENTER(3, "%s: Media count: %d\n", ast_sip_session_get_name(session), sdp->media_count);</span><br><span> </span><br><span>       if (session->inv_session && session->inv_session->state == PJSIP_INV_STATE_DISCONNECTED) {</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_log(LOG_ERROR, "Failed to handle incoming SDP. Session has been already disconnected\n");</span><br><span style="color: hsl(0, 100%, 40%);">-         SCOPE_EXIT_RTN_VALUE(-1, "Already disconnected\n");</span><br><span style="color: hsl(120, 100%, 40%);">+         SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Failed to handle incoming SDP. Session has been already disconnected\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_sip_session_get_name(session));</span><br><span>  }</span><br><span> </span><br><span>        /* It is possible for SDP deferral to have already created a pending topology */</span><br><span>     if (!session->pending_media_state->topology) {</span><br><span>                 session->pending_media_state->topology = ast_stream_topology_alloc();</span><br><span>          if (!session->pending_media_state->topology) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    SCOPE_EXIT_RTN_VALUE(-1, "No topology\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                  SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc pending topology\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_sip_session_get_name(session));</span><br><span>          }</span><br><span>    }</span><br><span> </span><br><span>@@ -770,6 +789,7 @@</span><br><span>          enum ast_media_type type;</span><br><span>            struct ast_stream *stream = NULL;</span><br><span>            pjmedia_sdp_media *remote_stream = sdp->media[i];</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_ENTER(4, "%s: Processing stream %d\n", ast_sip_session_get_name(session), i);</span><br><span> </span><br><span>            /* We need a null-terminated version of the media string */</span><br><span>          ast_copy_pj_str(media, &sdp->media[i]->desc.media, sizeof(media));</span><br><span>@@ -778,6 +798,8 @@</span><br><span>           /* See if we have an already existing stream, which can occur from SDP deferral checking */</span><br><span>          if (i < ast_stream_topology_get_count(session->pending_media_state->topology)) {</span><br><span>                    stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Using existing pending stream %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                          ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>          }</span><br><span>            if (!stream) {</span><br><span>                       struct ast_stream *existing_stream = NULL;</span><br><span>@@ -787,6 +809,8 @@</span><br><span>                     if (session->active_media_state->topology &&</span><br><span>                           (i < ast_stream_topology_get_count(session->active_media_state->topology))) {</span><br><span>                               existing_stream = ast_stream_topology_get_stream(session->active_media_state->topology, i);</span><br><span style="color: hsl(120, 100%, 40%);">+                             ast_trace(-1, "%s: Found existing active stream %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                                   ast_str_tmp(128, ast_stream_to_str(existing_stream, &STR_TMP)));</span><br><span> </span><br><span>                             if (ast_stream_get_state(existing_stream) != AST_STREAM_STATE_REMOVED) {</span><br><span>                                     stream_name = (char *)ast_stream_get_name(existing_stream);</span><br><span>@@ -796,22 +820,34 @@</span><br><span> </span><br><span>                      if (ast_strlen_zero(stream_name)) {</span><br><span>                          if (ast_asprintf(&stream_name, "%s-%d", ast_codec_media_type2str(type), i) < 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                      return -1;</span><br><span style="color: hsl(120, 100%, 40%);">+                                    handled = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+                                  SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc stream name\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                             ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>                               }</span><br><span style="color: hsl(120, 100%, 40%);">+                             ast_trace(-1, "%s: Using %s for new stream name\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                                      stream_name);</span><br><span>                        }</span><br><span> </span><br><span>                        stream = ast_stream_alloc(stream_name, type);</span><br><span>                        if (!stream) {</span><br><span style="color: hsl(0, 100%, 40%);">-                          SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create stream\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                           handled = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+                          SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc stream\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                  ast_sip_session_get_name(session));</span><br><span>                         }</span><br><span> </span><br><span>                        if (!ast_strlen_zero(stream_label)) {</span><br><span>                                ast_stream_set_metadata(stream, "SDP:LABEL", stream_label);</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_trace(-1, "%s: Using %s for new stream label\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                                     stream_label);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>                     }</span><br><span> </span><br><span>                        if (ast_stream_topology_set_stream(session->pending_media_state->topology, i, stream)) {</span><br><span>                               ast_stream_free(stream);</span><br><span style="color: hsl(0, 100%, 40%);">-                                SCOPE_EXIT_RTN_VALUE(-1, "Couldn't set stream\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                              handled = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+                          SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't set stream in topology\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                        ast_sip_session_get_name(session));</span><br><span>                         }</span><br><span> </span><br><span>                        /* For backwards compatibility with the core the default audio stream is always sendrecv */</span><br><span>@@ -832,19 +868,21 @@</span><br><span>                  } else {</span><br><span>                             ast_stream_set_state(stream, AST_STREAM_STATE_SENDRECV);</span><br><span>                     }</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Using new stream %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>          }</span><br><span> </span><br><span>                session_media = ast_sip_session_media_state_add(session, session->pending_media_state, ast_media_type_from_str(media), i);</span><br><span>                if (!session_media) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   SCOPE_EXIT_RTN_VALUE(-1, "Couldn't add session media\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                       SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc session media\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                           ast_sip_session_get_name(session));</span><br><span>                 }</span><br><span> </span><br><span>                /* If this stream is already declined mark it as such, or mark it as such if we've reached the limit */</span><br><span>          if (!remote_stream->desc.port || is_stream_limitation_reached(type, session->endpoint, type_streams)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                           ast_codec_media_type2str(type), i);</span><br><span>                  remove_stream_from_bundle(session_media, stream);</span><br><span style="color: hsl(0, 100%, 40%);">-                       continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Declining incoming SDP media stream %s'\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                              ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>               }</span><br><span> </span><br><span>                set_mid_and_bundle_group(session, session_media, sdp, remote_stream);</span><br><span>@@ -852,69 +890,70 @@</span><br><span> </span><br><span>            if (session_media->handler) {</span><br><span>                     handler = session_media->handler;</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_debug(1, "Negotiating incoming SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                             ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Negotiating incoming SDP media stream %s using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span>                                session_media->handler->id);</span><br><span>                   res = handler->negotiate_incoming_sdp_stream(session, session_media, sdp, i, stream);</span><br><span>                     if (res < 0) {</span><br><span>                            /* Catastrophic failure. Abort! */</span><br><span style="color: hsl(0, 100%, 40%);">-                              SCOPE_EXIT_RTN_VALUE(-1, "Couldn't negotiate incoming sdp stream\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                           SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't negotiate stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                   ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>                      } else if (res == 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                          ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                   ast_codec_media_type2str(type), i);</span><br><span>                          remove_stream_from_bundle(session_media, stream);</span><br><span style="color: hsl(0, 100%, 40%);">-                               continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                             SCOPE_EXIT_EXPR(continue, "%s: Declining incoming SDP media stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                   ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>                       } else if (res > 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_debug(1, "Media stream '%s' handled by %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                     ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(0, 100%, 40%);">-                                       session_media->handler->id);</span><br><span style="color: hsl(0, 100%, 40%);">-                              /* Handled by this handler. Move to the next stream */</span><br><span>                               handled = 1;</span><br><span>                                 ++type_streams[type];</span><br><span style="color: hsl(0, 100%, 40%);">-                           continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                             /* Handled by this handler. Move to the next stream */</span><br><span style="color: hsl(120, 100%, 40%);">+                                SCOPE_EXIT_EXPR(continue, "%s: Media stream %s handled by %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                    ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                                 session_media->handler->id);</span><br><span>                   }</span><br><span>            }</span><br><span> </span><br><span>                handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);</span><br><span>               if (!handler_list) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);</span><br><span style="color: hsl(0, 100%, 40%);">-                      continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Media stream %s has no registered handlers\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>               }</span><br><span>            AST_LIST_TRAVERSE(&handler_list->list, handler, next) {</span><br><span>                       if (handler == session_media->handler) {</span><br><span>                          continue;</span><br><span>                    }</span><br><span style="color: hsl(0, 100%, 40%);">-                       ast_debug(1, "Negotiating incoming SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                             ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_trace(-1, "%s: Negotiating incoming SDP media stream %s using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span>                                handler->id);</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>                   res = handler->negotiate_incoming_sdp_stream(session, session_media, sdp, i, stream);</span><br><span>                     if (res < 0) {</span><br><span>                            /* Catastrophic failure. Abort! */</span><br><span style="color: hsl(0, 100%, 40%);">-                              return -1;</span><br><span style="color: hsl(120, 100%, 40%);">+                            handled = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+                          SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't negotiate stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                   ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>                      } else if (res == 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                          ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                   ast_codec_media_type2str(type), i);</span><br><span>                          remove_stream_from_bundle(session_media, stream);</span><br><span style="color: hsl(120, 100%, 40%);">+                             ast_trace(-1, "%s: Declining incoming SDP media stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                       ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>                               continue;</span><br><span>                    } else if (res > 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_debug(1, "Media stream '%s' handled by %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                     ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(0, 100%, 40%);">-                                       handler->id);</span><br><span style="color: hsl(0, 100%, 40%);">-                                /* Handled by this handler. Move to the next stream */</span><br><span>                               session_media_set_handler(session_media, handler);</span><br><span>                           handled = 1;</span><br><span>                                 ++type_streams[type];</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_trace(-1, "%s: Media stream %s handled by %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                        ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                                 session_media->handler->id);</span><br><span>                           break;</span><br><span>                       }</span><br><span>            }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT("%s: Done with stream %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                  ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>  }</span><br><span style="color: hsl(0, 100%, 40%);">-       if (!handled) {</span><br><span style="color: hsl(0, 100%, 40%);">-         SCOPE_EXIT_RTN_VALUE(-1, "Not handled\n");</span><br><span style="color: hsl(0, 100%, 40%);">-    }</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN_VALUE(0, "Handled.  Active: %s  Pending: %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_str_tmp(256, ast_stream_topology_to_str(session->active_media_state->topology, &STR_TMP)),</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP))</span><br><span style="color: hsl(0, 100%, 40%);">-                );</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+end:</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_EXIT_RTN_VALUE(handled ? 0 : -1, "%s: Handled? %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+              handled ? "yes" : "no");</span><br><span> }</span><br><span> </span><br><span> static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *session_media,</span><br><span>@@ -958,13 +997,13 @@</span><br><span> </span><br><span>     handler = session_media->handler;</span><br><span>         if (handler) {</span><br><span style="color: hsl(0, 100%, 40%);">-          ast_debug(1, "Applying negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                      ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_debug(4, "%s: Applying negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),</span><br><span>                         handler->id);</span><br><span>             res = handler->apply_negotiated_sdp_stream(session, session_media, local, remote, index, asterisk_stream);</span><br><span>                if (res >= 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                      ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                               ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_debug(4, "%s: Applied negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),</span><br><span>                                 handler->id);</span><br><span>                     SCOPE_EXIT_RTN_VALUE(0,  "%s: Applied negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span>                            ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),</span><br><span>@@ -977,16 +1016,15 @@</span><br><span> </span><br><span>    handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);</span><br><span>       if (!handler_list) {</span><br><span style="color: hsl(0, 100%, 40%);">-            ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);</span><br><span style="color: hsl(0, 100%, 40%);">-              SCOPE_EXIT_RTN_VALUE(-1, "%s: No registered SDP handlers for media type '%s'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                      ast_sip_session_get_name(session), media);</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_debug(4, "%s: No registered SDP handlers for media type '%s'\n", ast_sip_session_get_name(session), media);</span><br><span style="color: hsl(120, 100%, 40%);">+             return -1;</span><br><span>   }</span><br><span>    AST_LIST_TRAVERSE(&handler_list->list, handler, next) {</span><br><span>               if (handler == session_media->handler) {</span><br><span>                  continue;</span><br><span>            }</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_debug(1, "Applying negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                      ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_debug(4, "%s: Applying negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),</span><br><span>                         handler->id);</span><br><span>             res = handler->apply_negotiated_sdp_stream(session, session_media, local, remote, index, asterisk_stream);</span><br><span>                if (res < 0) {</span><br><span>@@ -995,8 +1033,8 @@</span><br><span>                             ast_sip_session_get_name(session), handler->id, res);</span><br><span>             }</span><br><span>            if (res > 0) {</span><br><span style="color: hsl(0, 100%, 40%);">-                       ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                               ast_codec_media_type2str(session_media->type),</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_debug(4, "%s: Applied negotiated SDP media stream '%s' using %s SDP handler\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                         ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),</span><br><span>                                 handler->id);</span><br><span>                     /* Handled by this handler. Move to the next stream */</span><br><span>                       session_media_set_handler(session_media, handler);</span><br><span>@@ -1007,9 +1045,8 @@</span><br><span> </span><br><span>       res = 0;</span><br><span>     if (session_media->handler && session_media->handler->stream_stop) {</span><br><span style="color: hsl(0, 100%, 40%);">-           res = 1;</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_debug(1, "Stopping SDP media stream '%s' as it is not currently negotiated\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_codec_media_type2str(session_media->type));</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_debug(4, "%s: Stopping SDP media stream '%s' as it is not currently negotiated\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type));</span><br><span>                session_media->handler->stream_stop(session_media);</span><br><span>    }</span><br><span> </span><br><span>@@ -1037,17 +1074,17 @@</span><br><span>                      active_media_state_clone =</span><br><span>                           ast_sip_session_media_state_clone(session->active_media_state);</span><br><span>                   if (!active_media_state_clone) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_log(LOG_WARNING, "Unable to clone active media state for channel '%s'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                 session->channel ? ast_channel_name(session->channel) : "unknown");</span><br><span style="color: hsl(0, 100%, 40%);">-                             SCOPE_EXIT_RTN_VALUE(-1, "Unable to clone active media state\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                           ast_log(LOG_WARNING, "%s: Unable to clone active media state\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                    ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+                           return -1;</span><br><span>                   }</span><br><span> </span><br><span>                        ast_sip_session_media_state_free(session->pending_media_state);</span><br><span>                   session->pending_media_state = active_media_state_clone;</span><br><span>          } else {</span><br><span style="color: hsl(0, 100%, 40%);">-                        ast_log(LOG_WARNING, "No pending or active media state for channel '%s'\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                           session->channel ? ast_channel_name(session->channel) : "unknown");</span><br><span style="color: hsl(0, 100%, 40%);">-                     SCOPE_EXIT_RTN_VALUE(-1, "No media state\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_log(LOG_WARNING, "%s: No pending or active media state\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                              ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+                   return -1;</span><br><span>           }</span><br><span>    }</span><br><span> </span><br><span>@@ -1058,8 +1095,8 @@</span><br><span>         */</span><br><span>  if (ast_stream_topology_get_count(session->pending_media_state->topology) != local->media_count</span><br><span>             || AST_VECTOR_SIZE(&session->pending_media_state->sessions) != local->media_count) {</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_log(LOG_WARNING, "Local SDP for channel '%s' contains %d media streams while we expected it to contain %u\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                     session->channel ? ast_channel_name(session->channel) : "unknown",</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_log(LOG_WARNING, "%s: Local SDP contains %d media streams while we expected it to contain %u\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_sip_session_get_name(session),</span><br><span>                   ast_stream_topology_get_count(session->pending_media_state->topology), local->media_count);</span><br><span>                 SCOPE_EXIT_RTN_VALUE(-1, "Media stream count mismatch\n");</span><br><span>         }</span><br><span>@@ -1306,6 +1343,7 @@</span><br><span>    struct ast_sip_session_media_state *pending_media_state;</span><br><span>     /*! Active media state at the time of the original request */</span><br><span>        struct ast_sip_session_media_state *active_media_state;</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>    AST_LIST_ENTRY(ast_sip_session_delayed_request) next;</span><br><span> };</span><br><span> </span><br><span>@@ -1351,10 +1389,8 @@</span><br><span> static int send_delayed_request(struct ast_sip_session *session, struct ast_sip_session_delayed_request *delay)</span><br><span> {</span><br><span>     int res;</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-        ast_debug(3, "Endpoint '%s(%s)' sending delayed %s request.\n",</span><br><span style="color: hsl(0, 100%, 40%);">-               ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_ENTER(3, "%s: sending delayed %s request\n",</span><br><span style="color: hsl(120, 100%, 40%);">+          ast_sip_session_get_name(session),</span><br><span>           delayed_method2str(delay->method));</span><br><span> </span><br><span>   switch (delay->method) {</span><br><span>@@ -1366,7 +1402,7 @@</span><br><span>          /* Ownership of media state transitions to ast_sip_session_refresh */</span><br><span>                delay->pending_media_state = NULL;</span><br><span>                delay->active_media_state = NULL;</span><br><span style="color: hsl(0, 100%, 40%);">-            return res;</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));</span><br><span>      case DELAYED_METHOD_UPDATE:</span><br><span>          res = sip_session_refresh(session, delay->on_request_creation,</span><br><span>                    delay->on_sdp_creation, delay->on_response,</span><br><span>@@ -1375,14 +1411,15 @@</span><br><span>          /* Ownership of media state transitions to ast_sip_session_refresh */</span><br><span>                delay->pending_media_state = NULL;</span><br><span>                delay->active_media_state = NULL;</span><br><span style="color: hsl(0, 100%, 40%);">-            return res;</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));</span><br><span>      case DELAYED_METHOD_BYE:</span><br><span>             ast_sip_session_terminate(session, 0);</span><br><span style="color: hsl(0, 100%, 40%);">-          return 0;</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT_RTN_VALUE(0, "%s: Terminating session on delayed BYE\n", ast_sip_session_get_name(session));</span><br><span>    }</span><br><span style="color: hsl(0, 100%, 40%);">-       ast_log(LOG_WARNING, "Don't know how to send delayed %s(%d) request.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_WARNING, "%s: Don't know how to send delayed %s(%d) request.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+               ast_sip_session_get_name(session),</span><br><span>           delayed_method2str(delay->method), delay->method);</span><br><span style="color: hsl(0, 100%, 40%);">-        return -1;</span><br><span> }</span><br><span> </span><br><span> /*!</span><br><span>@@ -1401,6 +1438,7 @@</span><br><span>   struct ast_sip_session_delayed_request *delay;</span><br><span>       int found = 0;</span><br><span>       int res = 0;</span><br><span style="color: hsl(120, 100%, 40%);">+  SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     AST_LIST_TRAVERSE_SAFE_BEGIN(&session->delayed_requests, delay, next) {</span><br><span>               switch (delay->method) {</span><br><span>@@ -1408,6 +1446,8 @@</span><br><span>                  break;</span><br><span>               case DELAYED_METHOD_UPDATE:</span><br><span>                  AST_LIST_REMOVE_CURRENT(next);</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_trace(-1, "%s: Sending delayed %s request\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                                delayed_method2str(delay->method));</span><br><span>                       res = send_delayed_request(session, delay);</span><br><span>                  delayed_request_free(delay);</span><br><span>                         if (!res) {</span><br><span>@@ -1426,7 +1466,7 @@</span><br><span>  AST_LIST_TRAVERSE_SAFE_END;</span><br><span> </span><br><span>      ao2_ref(session, -1);</span><br><span style="color: hsl(0, 100%, 40%);">-   return res;</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> /*!</span><br><span>@@ -1446,6 +1486,7 @@</span><br><span>      int found = 0;</span><br><span>       int res = 0;</span><br><span>         int timer_running;</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     /* re-INVITE collision timer running? */</span><br><span>     timer_running = pj_timer_entry_running(&session->rescheduled_reinvite);</span><br><span>@@ -1464,6 +1505,8 @@</span><br><span>               }</span><br><span>            if (found) {</span><br><span>                         AST_LIST_REMOVE_CURRENT(next);</span><br><span style="color: hsl(120, 100%, 40%);">+                        ast_trace(-1, "%s: Sending delayed %s request\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                                delayed_method2str(delay->method));</span><br><span>                       res = send_delayed_request(session, delay);</span><br><span>                  delayed_request_free(delay);</span><br><span>                         if (!res) {</span><br><span>@@ -1474,7 +1517,7 @@</span><br><span>  AST_LIST_TRAVERSE_SAFE_END;</span><br><span> </span><br><span>      ao2_ref(session, -1);</span><br><span style="color: hsl(0, 100%, 40%);">-   return res;</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> /*!</span><br><span>@@ -1491,6 +1534,7 @@</span><br><span> {</span><br><span>         struct ast_sip_session *session = vsession;</span><br><span>  int res;</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (session->inv_session->invite_tsx) {</span><br><span>                /*</span><br><span>@@ -1503,7 +1547,7 @@</span><br><span>           res = invite_terminated(session);</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   return res;</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> /*!</span><br><span>@@ -1550,8 +1594,8 @@</span><br><span>      int queue_head)</span><br><span> {</span><br><span>         struct ast_sip_session_delayed_request *delay = delayed_request_alloc(method,</span><br><span style="color: hsl(0, 100%, 40%);">-           on_request, on_sdp_creation, on_response, generate_new_sdp, pending_media_state,</span><br><span style="color: hsl(0, 100%, 40%);">-                active_media_state);</span><br><span style="color: hsl(120, 100%, 40%);">+                  on_request, on_sdp_creation, on_response, generate_new_sdp, pending_media_state,</span><br><span style="color: hsl(120, 100%, 40%);">+                      active_media_state);</span><br><span> </span><br><span>     if (!delay) {</span><br><span>                ast_sip_session_media_state_free(pending_media_state);</span><br><span>@@ -1645,7 +1689,8 @@</span><br><span>       ast_channel_lock(session->channel);</span><br><span>       pjsip_from_domain = pbx_builtin_getvar_helper(session->channel, "SIPFROMDOMAIN");</span><br><span>       if (!ast_strlen_zero(pjsip_from_domain)) {</span><br><span style="color: hsl(0, 100%, 40%);">-              ast_debug(3, "From header domain reset by channel variable SIPFROMDOMAIN (%s)\n", pjsip_from_domain);</span><br><span style="color: hsl(120, 100%, 40%);">+               ast_debug(3, "%s: From header domain reset by channel variable SIPFROMDOMAIN (%s)\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_sip_session_get_name(session), pjsip_from_domain);</span><br><span>               pj_strdup2(dlg_pool, &dlg_info_uri->host, pjsip_from_domain);</span><br><span>         }</span><br><span>    ast_channel_unlock(session->channel);</span><br><span>@@ -2469,6 +2514,7 @@</span><br><span>     return sip_session_refresh(session, on_request_creation, on_sdp_creation,</span><br><span>            on_response, method, generate_new_sdp, media_state, NULL, 0);</span><br><span> }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> int ast_sip_session_regenerate_answer(struct ast_sip_session *session,</span><br><span>               ast_sip_session_sdp_creation_cb on_sdp_creation)</span><br><span> {</span><br><span>@@ -2633,7 +2679,7 @@</span><br><span> </span><br><span>            handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);</span><br><span>               if (!handler_list) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_debug(3, "%s: No registered SDP handlers for media type '%s'\n", ast_sip_session_get_name(session), media);</span><br><span>                    continue;</span><br><span>            }</span><br><span>            AST_LIST_TRAVERSE(&handler_list->list, handler, next) {</span><br><span>@@ -2894,7 +2940,7 @@</span><br><span>       const char *endpoint_name = session->endpoint ?</span><br><span>           ast_strdupa(ast_sorcery_object_get_id(session->endpoint)) : "<none>";</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-    ast_debug(3, "Destroying SIP session with endpoint %s\n", endpoint_name);</span><br><span style="color: hsl(120, 100%, 40%);">+   ast_debug(3, "%s: Destroying SIP session\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>       ast_test_suite_event_notify("SESSION_DESTROYING",</span><br><span>          "Endpoint: %s\r\n"</span><br><span>@@ -3211,18 +3257,19 @@</span><br><span>       }</span><br><span> </span><br><span>        inv = pjsip_dlg_get_inv_session(dlg);</span><br><span style="color: hsl(120, 100%, 40%);">+ session = inv->mod_data[session_module.id];</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>     if (PJSIP_INV_STATE_CONFIRMED <= inv->state) {</span><br><span>                 /*</span><br><span>            * We cannot handle reINVITE authentication at this</span><br><span>           * time because the reINVITE transaction is still in</span><br><span>                  * progress.</span><br><span>                  */</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_debug(1, "A reINVITE is being challenged.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          ast_debug(3, "%s: A reINVITE is being challenged\n", ast_sip_session_get_name(session));</span><br><span>           return PJ_FALSE;</span><br><span>     }</span><br><span style="color: hsl(0, 100%, 40%);">-       ast_debug(1, "Initial INVITE is being challenged.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+      ast_debug(3, "%s: Initial INVITE is being challenged.\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-     session = inv->mod_data[session_module.id];</span><br><span> </span><br><span>   if (ast_sip_create_request_with_auth(&session->endpoint->outbound_auths, rdata,</span><br><span>            tsx->last_tx, &tdata)) {</span><br><span>@@ -3449,8 +3496,8 @@</span><br><span>              break;</span><br><span>       case PJSIP_INV_STATE_CONFIRMED:</span><br><span>              if (session->inv_session->invite_tsx) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   ast_debug(3, "Delay sending BYE to %s because of outstanding transaction...\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                       ast_sorcery_object_get_id(session->endpoint));</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_debug(3, "%s: Delay sending BYE because of outstanding transaction...\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_sip_session_get_name(session));</span><br><span>                  /* If this is delayed the only thing that will happen is a BYE request so we don't</span><br><span>                        * actually need to store the response code for when it happens.</span><br><span>                      */</span><br><span>@@ -3573,7 +3620,7 @@</span><br><span> </span><br><span>      if (session->ended_while_deferred) {</span><br><span>              /* Complete the session end started by the remote hangup. */</span><br><span style="color: hsl(0, 100%, 40%);">-            ast_debug(3, "Ending session (%p) after being deferred\n", session);</span><br><span style="color: hsl(120, 100%, 40%);">+                ast_debug(3, "%s: Ending session after being deferred\n", ast_sip_session_get_name(session));</span><br><span>              session->ended_while_deferred = 0;</span><br><span>                session_end(session);</span><br><span>        }</span><br><span>@@ -3637,7 +3684,8 @@</span><br><span> </span><br><span>        pickup_cfg = ast_get_chan_features_pickup_config(session->channel);</span><br><span>       if (!pickup_cfg) {</span><br><span style="color: hsl(0, 100%, 40%);">-              ast_log(LOG_ERROR, "Unable to retrieve pickup configuration options. Unable to detect call pickup extension\n");</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_log(LOG_ERROR, "%s: Unable to retrieve pickup configuration options. Unable to detect call pickup extension\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_sip_session_get_name(session));</span><br><span>          pickupexten = "";</span><br><span>  } else {</span><br><span>             pickupexten = ast_strdupa(pickup_cfg->pickupexten);</span><br><span>@@ -3789,20 +3837,22 @@</span><br><span>     pjsip_rdata_sdp_info *sdp_info;</span><br><span>      pjmedia_sdp_session *local = NULL;</span><br><span>   char buffer[AST_SOCKADDR_BUFLEN];</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(invite->session));</span><br><span style="color: hsl(120, 100%, 40%);">+       SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(invite->session));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> </span><br><span>        /* From this point on, any calls to pjsip_inv_terminate have the last argument as PJ_TRUE</span><br><span>     * so that we will be notified so we can destroy the session properly</span><br><span>         */</span><br><span> </span><br><span>      if (invite->session->inv_session->state == PJSIP_INV_STATE_DISCONNECTED) {</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_log(LOG_ERROR, "Session already DISCONNECTED [reason=%d (%s)]\n",</span><br><span style="color: hsl(120, 100%, 40%);">+               ast_trace_log(-1, LOG_ERROR, "%s: Session already DISCONNECTED [reason=%d (%s)]\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_sip_session_get_name(invite->session),</span><br><span>                        invite->session->inv_session->cause,</span><br><span>                        pjsip_get_status_text(invite->session->inv_session->cause)->ptr);</span><br><span> #ifdef HAVE_PJSIP_INV_SESSION_REF</span><br><span>           pjsip_inv_dec_ref(invite->session->inv_session);</span><br><span> #endif</span><br><span style="color: hsl(0, 100%, 40%);">-                SCOPE_EXIT_RTN_VALUE(-1, "Already disconnected\n");</span><br><span style="color: hsl(120, 100%, 40%);">+         SCOPE_EXIT_RTN_VALUE(-1);</span><br><span>    }</span><br><span> </span><br><span>        switch (get_destination(invite->session, invite->rdata)) {</span><br><span>@@ -3810,6 +3860,11 @@</span><br><span>            /* Things worked. Keep going */</span><br><span>              break;</span><br><span>       case SIP_GET_DEST_UNSUPPORTED_URI:</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_trace(-1, "%s: Call (%s:%s) to extension '%s' - unsupported uri\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_sip_session_get_name(invite->session),</span><br><span style="color: hsl(120, 100%, 40%);">+                 invite->rdata->tp_info.transport->type_name,</span><br><span style="color: hsl(120, 100%, 40%);">+                 pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),</span><br><span style="color: hsl(120, 100%, 40%);">+                    invite->session->exten);</span><br><span>               if (pjsip_inv_initial_answer(invite->session->inv_session, invite->rdata, 416, NULL, NULL, &tdata) == PJ_SUCCESS) {</span><br><span>                     ast_sip_session_send_response(invite->session, tdata);</span><br><span>            } else  {</span><br><span>@@ -3817,8 +3872,8 @@</span><br><span>            }</span><br><span>            goto end;</span><br><span>    case SIP_GET_DEST_EXTEN_PARTIAL:</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_debug(1, "Call from '%s' (%s:%s) to extension '%s' - partial match\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_sorcery_object_get_id(invite->session->endpoint),</span><br><span style="color: hsl(120, 100%, 40%);">+           ast_trace(-1, "%s: Call (%s:%s) to extension '%s' - partial match\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                       ast_sip_session_get_name(invite->session),</span><br><span>                        invite->rdata->tp_info.transport->type_name,</span><br><span>                        pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),</span><br><span>                   invite->session->exten);</span><br><span>@@ -3831,8 +3886,8 @@</span><br><span>               goto end;</span><br><span>    case SIP_GET_DEST_EXTEN_NOT_FOUND:</span><br><span>   default:</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_log(LOG_NOTICE, "Call from '%s' (%s:%s) to extension '%s' rejected because extension not found in context '%s'.\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                       ast_sorcery_object_get_id(invite->session->endpoint),</span><br><span style="color: hsl(120, 100%, 40%);">+           ast_trace_log(-1, LOG_NOTICE, "%s: Call (%s:%s) to extension '%s' rejected because extension not found in context '%s'.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_sip_session_get_name(invite->session),</span><br><span>                        invite->rdata->tp_info.transport->type_name,</span><br><span>                        pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),</span><br><span>                   invite->session->exten,</span><br><span>@@ -3865,6 +3920,11 @@</span><br><span>        * so let's go ahead and send a 100 Trying out to stop any</span><br><span>        * retransmissions.</span><br><span>   */</span><br><span style="color: hsl(120, 100%, 40%);">+   ast_trace(-1, "%s: Call (%s:%s) to extension '%s' sending 100 Trying\n",</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_sip_session_get_name(invite->session),</span><br><span style="color: hsl(120, 100%, 40%);">+         invite->rdata->tp_info.transport->type_name,</span><br><span style="color: hsl(120, 100%, 40%);">+         pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),</span><br><span style="color: hsl(120, 100%, 40%);">+            invite->session->exten);</span><br><span>       if (pjsip_inv_initial_answer(invite->session->inv_session, invite->rdata, 100, NULL, NULL, &tdata) != PJ_SUCCESS) {</span><br><span>             pjsip_inv_terminate(invite->session->inv_session, 500, PJ_TRUE);</span><br><span>               goto end;</span><br><span>@@ -3912,10 +3972,7 @@</span><br><span> #ifdef HAVE_PJSIP_INV_SESSION_REF</span><br><span>      pjsip_inv_dec_ref(invite->session->inv_session);</span><br><span> #endif</span><br><span style="color: hsl(0, 100%, 40%);">-        SCOPE_EXIT_RTN_VALUE(0, "Handled.  Active: %s  Pending: %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_str_tmp(256, ast_stream_topology_to_str(invite->session->active_media_state->topology, &STR_TMP)),</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_str_tmp(256, ast_stream_topology_to_str(invite->session->pending_media_state->topology, &STR_TMP))</span><br><span style="color: hsl(0, 100%, 40%);">-             );</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(invite->session));</span><br><span> }</span><br><span> </span><br><span> static void handle_new_invite_request(pjsip_rx_data *rdata)</span><br><span>@@ -4104,9 +4161,8 @@</span><br><span> {</span><br><span>        struct ast_sip_session *session = entry->user_data;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-      ast_debug(3, "Endpoint '%s(%s)' re-INVITE collision timer expired.\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                session->channel ? ast_channel_name(session->channel) : "");</span><br><span style="color: hsl(120, 100%, 40%);">+  ast_debug(3, "%s: re-INVITE collision timer expired.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+            ast_sip_session_get_name(session));</span><br><span> </span><br><span>      if (AST_LIST_EMPTY(&session->delayed_requests)) {</span><br><span>             /* No delayed request pending, so just return */</span><br><span>@@ -4150,13 +4206,12 @@</span><br><span>           ast_sip_session_media_state_free(pending_media_state);</span><br><span>               ast_sip_session_media_state_free(active_media_state);</span><br><span>                ast_log(LOG_ERROR, "%s: Failed to add delayed request\n", session_name);</span><br><span style="color: hsl(120, 100%, 40%);">+            return;</span><br><span>      }</span><br><span> </span><br><span>        if (pj_timer_entry_running(&session->rescheduled_reinvite)) {</span><br><span>                 /* Timer already running.  Something weird is going on. */</span><br><span style="color: hsl(0, 100%, 40%);">-              ast_debug(1, "Endpoint '%s(%s)' re-INVITE collision while timer running!!!\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                        ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                        session->channel ? ast_channel_name(session->channel) : "");</span><br><span style="color: hsl(120, 100%, 40%);">+          ast_log(LOG_ERROR, "%s: re-INVITE collision while timer running!!!\n", session_name);</span><br><span>              return;</span><br><span>      }</span><br><span> </span><br><span>@@ -4172,6 +4227,7 @@</span><br><span>        if (pjsip_endpt_schedule_timer(ast_sip_get_pjsip_endpoint(),</span><br><span>                 &session->rescheduled_reinvite, &tv) != PJ_SUCCESS) {</span><br><span>             ao2_ref(session, -1);</span><br><span style="color: hsl(120, 100%, 40%);">+         ast_log(LOG_ERROR, "%s: Couldn't schedule timer\n", session_name);</span><br><span>     }</span><br><span> }</span><br><span> </span><br><span>@@ -4230,10 +4286,8 @@</span><br><span> {</span><br><span>     struct ast_sip_session_supplement *supplement;</span><br><span>       struct pjsip_request_line req = rdata->msg_info.msg->line.req;</span><br><span style="color: hsl(0, 100%, 40%);">-    SCOPE_ENTER(1, "%s Method: %.*s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));</span><br><span style="color: hsl(120, 100%, 40%);">+      SCOPE_ENTER(3, "%s: Method is %.*s\n", ast_sip_session_get_name(session), (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-        ast_debug(3, "Method is %.*s\n", (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));</span><br><span>  AST_LIST_TRAVERSE(&session->supplements, supplement, next) {</span><br><span>          if (supplement->incoming_request && does_method_match(&req.method.name, supplement->method)) {</span><br><span>                     if (supplement->incoming_request(session, rdata)) {</span><br><span>@@ -4242,7 +4296,7 @@</span><br><span>               }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static void handle_session_begin(struct ast_sip_session *session)</span><br><span>@@ -4284,13 +4338,8 @@</span><br><span> {</span><br><span>         struct ast_sip_session_supplement *supplement;</span><br><span>       struct pjsip_status_line status = rdata->msg_info.msg->line.status;</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_ENTER(1, "%s Method: %.*s Status: %d  Priority %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr,</span><br><span style="color: hsl(0, 100%, 40%);">-         rdata->msg_info.msg->line.status.code,</span><br><span style="color: hsl(0, 100%, 40%);">-            response_priority == AST_SIP_SESSION_AFTER_MEDIA ? "after" : "before");</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-     ast_debug(3, "Response is %d %.*s\n", status.code, (int) pj_strlen(&status.reason),</span><br><span style="color: hsl(0, 100%, 40%);">-                       pj_strbuf(&status.reason));</span><br><span style="color: hsl(120, 100%, 40%);">+       SCOPE_ENTER(3, "%s: Response is %d %.*s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+              status.code, (int) pj_strlen(&status.reason), pj_strbuf(&status.reason));</span><br><span> </span><br><span>        AST_LIST_TRAVERSE(&session->supplements, supplement, next) {</span><br><span>          if (!(supplement->response_priority & response_priority)) {</span><br><span>@@ -4301,44 +4350,34 @@</span><br><span>                 }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int handle_incoming(struct ast_sip_session *session, pjsip_rx_data *rdata,</span><br><span>               enum ast_sip_session_response_priority response_priority)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-  SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(0, 100%, 40%);">-    ast_debug(3, "Received %s\n", rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ?</span><br><span style="color: hsl(0, 100%, 40%);">-                  "request" : "response");</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span>         if (rdata->msg_info.msg->type == PJSIP_REQUEST_MSG) {</span><br><span>          handle_incoming_request(session, rdata);</span><br><span>     } else {</span><br><span>             handle_incoming_response(session, rdata, response_priority);</span><br><span>         }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN_VALUE(0);</span><br><span style="color: hsl(120, 100%, 40%);">+      return 0;</span><br><span> }</span><br><span> </span><br><span> static void handle_outgoing_request(struct ast_sip_session *session, pjsip_tx_data *tdata)</span><br><span> {</span><br><span>        struct ast_sip_session_supplement *supplement;</span><br><span>       struct pjsip_request_line req = tdata->msg->line.req;</span><br><span style="color: hsl(0, 100%, 40%);">-     SCOPE_ENTER(1, "%s Method: %.*s\n",  ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-               (int) pj_strlen(&req.method.name),</span><br><span style="color: hsl(0, 100%, 40%);">-          pj_strbuf(&req.method.name));</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-       ast_debug(3, "Method is %.*s\n", (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-     ast_sip_message_apply_transport(session->endpoint->transport, tdata);</span><br><span style="color: hsl(120, 100%, 40%);">+   SCOPE_ENTER(3, "%s: Method is %.*s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+           (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));</span><br><span> </span><br><span>         AST_LIST_TRAVERSE(&session->supplements, supplement, next) {</span><br><span>          if (supplement->outgoing_request && does_method_match(&req.method.name, supplement->method)) {</span><br><span>                     supplement->outgoing_request(session, tdata);</span><br><span>             }</span><br><span>    }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static void handle_outgoing_response(struct ast_sip_session *session, pjsip_tx_data *tdata)</span><br><span>@@ -4346,29 +4385,24 @@</span><br><span>   struct ast_sip_session_supplement *supplement;</span><br><span>       struct pjsip_status_line status = tdata->msg->line.status;</span><br><span>     pjsip_cseq_hdr *cseq = pjsip_msg_find_hdr(tdata->msg, PJSIP_H_CSEQ, NULL);</span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_ENTER(1, "%s Method is %.*s, Response is %d %.*s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+       SCOPE_ENTER(3, "%s: Method is %.*s, Response is %d %.*s\n", ast_sip_session_get_name(session),</span><br><span>             (int) pj_strlen(&cseq->method.name),</span><br><span>          pj_strbuf(&cseq->method.name), status.code, (int) pj_strlen(&status.reason),</span><br><span>              pj_strbuf(&status.reason));</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>        if (!cseq) {</span><br><span style="color: hsl(0, 100%, 40%);">-            ast_log(LOG_ERROR, "Cannot send response due to missing sequence header");</span><br><span style="color: hsl(0, 100%, 40%);">-            SCOPE_EXIT_RTN("Missing cseq\n");</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_LOG_RTN(LOG_ERROR, "%s: Cannot send response due to missing sequence header",</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_sip_session_get_name(session));</span><br><span>  }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   ast_debug(3, "Method is %.*s, Response is %d %.*s\n", (int) pj_strlen(&cseq->method.name),</span><br><span style="color: hsl(0, 100%, 40%);">-             pj_strbuf(&cseq->method.name), status.code, (int) pj_strlen(&status.reason),</span><br><span style="color: hsl(0, 100%, 40%);">-         pj_strbuf(&status.reason));</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">- ast_sip_message_apply_transport(session->endpoint->transport, tdata);</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span>  AST_LIST_TRAVERSE(&session->supplements, supplement, next) {</span><br><span>          if (supplement->outgoing_response && does_method_match(&cseq->method.name, supplement->method)) {</span><br><span>                       supplement->outgoing_response(session, tdata);</span><br><span>            }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-   SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static int session_end(void *vsession)</span><br><span>@@ -4433,7 +4467,9 @@</span><br><span>  struct ast_sip_session *session, pjsip_rx_data *rdata)</span><br><span> {</span><br><span>  pjsip_msg *msg;</span><br><span style="color: hsl(0, 100%, 40%);">- SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+  ast_debug(3, "%s: Received %s\n", ast_sip_session_get_name(session), rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ?</span><br><span style="color: hsl(120, 100%, 40%);">+                 "request" : "response");</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> </span><br><span>   handle_incoming(session, rdata, AST_SIP_SESSION_BEFORE_MEDIA);</span><br><span>       msg = rdata->msg_info.msg;</span><br><span>@@ -4449,17 +4485,14 @@</span><br><span>               * SDP answer.</span><br><span>                */</span><br><span>          ast_debug(1,</span><br><span style="color: hsl(0, 100%, 40%);">-                    "Endpoint '%s(%s)': Ending session due to incomplete SDP negotiation.  %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                 ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                        session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+                   "%s: Ending session due to incomplete SDP negotiation.  %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_sip_session_get_name(session),</span><br><span>                   pjsip_rx_data_get_info(rdata));</span><br><span>              if (pjsip_inv_end_session(inv, 400, NULL, &tdata) == PJ_SUCCESS</span><br><span>                  && tdata) {</span><br><span>                  ast_sip_session_send_request(session, tdata);</span><br><span>                }</span><br><span>    }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN();</span><br><span> }</span><br><span> </span><br><span> static void session_inv_on_state_changed(pjsip_inv_session *inv, pjsip_event *e)</span><br><span>@@ -4492,7 +4525,8 @@</span><br><span>               handle_incoming_before_media(inv, session, e->body.rx_msg.rdata);</span><br><span>                 break;</span><br><span>       case PJSIP_EVENT_TSX_STATE:</span><br><span style="color: hsl(0, 100%, 40%);">-             ast_debug(3, "Source of transaction state change is %s\n", pjsip_event_str(e->body.tsx_state.type));</span><br><span style="color: hsl(120, 100%, 40%);">+             ast_debug(3, "%s: Source of transaction state change is %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                   pjsip_event_str(e->body.tsx_state.type));</span><br><span>                 /* Transaction state changes are prompted by some other underlying event. */</span><br><span>                 switch(e->body.tsx_state.type) {</span><br><span>          case PJSIP_EVENT_TX_MSG:</span><br><span>@@ -4528,7 +4562,7 @@</span><br><span> </span><br><span>         if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {</span><br><span>                 if (session->defer_end) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_debug(3, "Deferring session (%p) end\n", session);</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_debug(3, "%s: Deferring session end\n", ast_sip_session_get_name(session));</span><br><span>                    session->ended_while_deferred = 1;</span><br><span>                        SCOPE_EXIT_RTN("Deferring\n");</span><br><span>             }</span><br><span>@@ -4638,7 +4672,8 @@</span><br><span>                                            SCOPE_EXIT_RTN("Non 2XX final response\n");</span><br><span>                                        }</span><br><span>                                    if (inv->state == PJSIP_INV_STATE_CONFIRMED) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                               ast_debug(1, "reINVITE received final response code %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                          ast_debug(1, "%s: reINVITE received final response code %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                                      ast_sip_session_get_name(session),</span><br><span>                                                   tsx->status_code);</span><br><span>                                                if ((tsx->status_code == 401 || tsx->status_code == 407)</span><br><span>                                                       && !ast_sip_create_request_with_auth(</span><br><span>@@ -4711,15 +4746,13 @@</span><br><span>                                                      pjsip_rx_data_get_info(e->body.tsx_state.src.rdata),</span><br><span>                                                      sdp_negotiation_done ? "complete" : "incomplete");</span><br><span>                                               if (!sdp_negotiation_done) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                                    ast_debug(1, "Endpoint '%s(%s)': Incomplete SDP negotiation cancelled session.  %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                                                ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                                                                session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+                                                   ast_debug(1, "%s: Incomplete SDP negotiation cancelled session.  %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                                             ast_sip_session_get_name(session),</span><br><span>                                                           pjsip_rx_data_get_info(e->body.tsx_state.src.rdata));</span><br><span>                                             } else if (pjsip_inv_end_session(inv, 500, NULL, &tdata) == PJ_SUCCESS</span><br><span>                                                   && tdata) {</span><br><span style="color: hsl(0, 100%, 40%);">-                                                     ast_debug(1, "Endpoint '%s(%s)': Ending session due to RFC5407 race condition.  %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                                                                ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                                                                session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+                                                   ast_debug(1, "%s: Ending session due to RFC5407 race condition.  %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                                             ast_sip_session_get_name(session),</span><br><span>                                                           pjsip_rx_data_get_info(e->body.tsx_state.src.rdata));</span><br><span>                                                     ast_sip_session_send_request(session, tdata);</span><br><span>                                                }</span><br><span>@@ -4731,7 +4764,8 @@</span><br><span>                    if (tsx->role == PJSIP_ROLE_UAC) {</span><br><span>                                if (tsx->state == PJSIP_TSX_STATE_COMPLETED) {</span><br><span>                                    /* This means we got a final response to our outgoing method */</span><br><span style="color: hsl(0, 100%, 40%);">-                                 ast_debug(1, "%.*s received final response code %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                      ast_debug(1, "%s: %.*s received final response code %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                          ast_sip_session_get_name(session),</span><br><span>                                           (int) pj_strlen(&tsx->method.name), pj_strbuf(&tsx->method.name),</span><br><span>                                              tsx->status_code);</span><br><span>                                        if ((tsx->status_code == 401 || tsx->status_code == 407)</span><br><span>@@ -4774,9 +4808,8 @@</span><br><span> </span><br><span>   if (tsx->method.id == PJSIP_INVITE_METHOD) {</span><br><span>              if (tsx->state == PJSIP_TSX_STATE_PROCEEDING) {</span><br><span style="color: hsl(0, 100%, 40%);">-                      ast_debug(3, "Endpoint '%s(%s)' INVITE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                          ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                                session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+                   ast_debug(3, "%s: INVITE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                              ast_sip_session_get_name(session),</span><br><span>                           pjsip_tsx_state_str(tsx->state));</span><br><span>                         check_delayed_requests(session, invite_proceeding);</span><br><span>          } else if (tsx->state == PJSIP_TSX_STATE_TERMINATED) {</span><br><span>@@ -4785,18 +4818,16 @@</span><br><span>                   * queuing delayed requests, no matter what event caused</span><br><span>                      * the transaction to terminate.</span><br><span>                      */</span><br><span style="color: hsl(0, 100%, 40%);">-                     ast_debug(3, "Endpoint '%s(%s)' INVITE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                          ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                                session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+                   ast_debug(3, "%s: INVITE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                              ast_sip_session_get_name(session),</span><br><span>                           pjsip_tsx_state_str(tsx->state));</span><br><span>                         check_delayed_requests(session, invite_terminated);</span><br><span>          }</span><br><span>    } else if (tsx->role == PJSIP_ROLE_UAC</span><br><span>            && tsx->state == PJSIP_TSX_STATE_COMPLETED</span><br><span>                && !pj_strcmp2(&tsx->method.name, "UPDATE")) {</span><br><span style="color: hsl(0, 100%, 40%);">-         ast_debug(3, "Endpoint '%s(%s)' UPDATE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(0, 100%, 40%);">-                  ast_sorcery_object_get_id(session->endpoint),</span><br><span style="color: hsl(0, 100%, 40%);">-                        session->channel ? ast_channel_name(session->channel) : "",</span><br><span style="color: hsl(120, 100%, 40%);">+           ast_debug(3, "%s: UPDATE delay check. tsx-state:%s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_sip_session_get_name(session),</span><br><span>                   pjsip_tsx_state_str(tsx->state));</span><br><span>                 check_delayed_requests(session, update_completed);</span><br><span>   }</span><br><span>@@ -4936,16 +4967,15 @@</span><br><span>  pjmedia_sdp_session *local;</span><br><span>  int i;</span><br><span>       int stream;</span><br><span style="color: hsl(0, 100%, 40%);">-     SCOPE_ENTER(1, "%s Topology: %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-                ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP)));</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {</span><br><span style="color: hsl(0, 100%, 40%);">-            ast_log(LOG_ERROR, "Failed to create session SDP. Session has been already disconnected\n");</span><br><span style="color: hsl(0, 100%, 40%);">-          SCOPE_EXIT_RTN_VALUE(NULL, "Disconnected\n");</span><br><span style="color: hsl(120, 100%, 40%);">+               SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Failed to create session SDP. Session has been already disconnected\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                      ast_sip_session_get_name(session));</span><br><span>  }</span><br><span> </span><br><span>        if (!inv->pool_prov || !(local = PJ_POOL_ZALLOC_T(inv->pool_prov, pjmedia_sdp_session))) {</span><br><span style="color: hsl(0, 100%, 40%);">-                SCOPE_EXIT_RTN_VALUE(NULL, "Pool alloc failure\n");</span><br><span style="color: hsl(120, 100%, 40%);">+         SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Pool allocation failure\n", ast_sip_session_get_name(session));</span><br><span>     }</span><br><span> </span><br><span>        if (!offer) {</span><br><span>@@ -4970,28 +5000,34 @@</span><br><span>                      session->pending_media_state->topology = ast_stream_topology_clone(session->endpoint->media.topology);</span><br><span>           }</span><br><span>            if (!session->pending_media_state->topology) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    SCOPE_EXIT_RTN_VALUE(NULL, "No pending topology\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                        SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: No pending media state topology\n", ast_sip_session_get_name(session));</span><br><span>             }</span><br><span>    }</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+ ast_trace(-1, "%s: Processing streams\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>    for (i = 0; i < ast_stream_topology_get_count(session->pending_media_state->topology); ++i) {</span><br><span>               struct ast_sip_session_media *session_media;</span><br><span style="color: hsl(0, 100%, 40%);">-            struct ast_stream *stream;</span><br><span style="color: hsl(120, 100%, 40%);">+            struct ast_stream *stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);</span><br><span>                 unsigned int streams = local->media_count;</span><br><span style="color: hsl(120, 100%, 40%);">+         SCOPE_ENTER(4, "%s: Processing stream %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                     ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span> </span><br><span>              /* This code does not enforce any maximum stream count limitations as that is done on either</span><br><span>                  * the handling of an incoming SDP offer or on the handling of a session refresh.</span><br><span>             */</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-         stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span>            session_media = ast_sip_session_media_state_add(session, session->pending_media_state, ast_stream_get_type(stream), i);</span><br><span>           if (!session_media) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add state\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                     local = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+                 SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc/add session media for stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>               }</span><br><span> </span><br><span>                if (add_sdp_streams(session_media, session, local, offer, stream)) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add stream\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                    local = NULL;</span><br><span style="color: hsl(120, 100%, 40%);">+                 SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't add sdp streams for stream %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span>               }</span><br><span> </span><br><span>                /* If a stream was actually added then add any additional details */</span><br><span>@@ -5005,23 +5041,38 @@</span><br><span>                               attr = pjmedia_sdp_attr_create(inv->pool_prov, "mid", pj_cstr(&stmp, session_media->mid));</span><br><span>                               pjmedia_sdp_attr_add(&media->attr_count, media->attr, attr);</span><br><span>                       }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+                   ast_trace(-1, "%s: Stream %s added%s%s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                            S_COR(!ast_strlen_zero(session_media->mid), " with mid ", ""), S_OR(session_media->mid, ""));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>          }</span><br><span> </span><br><span>                /* Ensure that we never exceed the maximum number of streams PJMEDIA will allow. */</span><br><span>          if (local->media_count == PJMEDIA_MAX_SDP_MEDIA) {</span><br><span style="color: hsl(0, 100%, 40%);">-                   break;</span><br><span style="color: hsl(120, 100%, 40%);">+                        SCOPE_EXIT_EXPR(break, "%s: Stream %s exceeded max pjmedia count of %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+                          ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),</span><br><span style="color: hsl(120, 100%, 40%);">+                         PJMEDIA_MAX_SDP_MEDIA);</span><br><span>              }</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT("%s: Done with %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                 ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>        }</span><br><span> </span><br><span>        /* Add any bundle groups that are present on the media state */</span><br><span style="color: hsl(120, 100%, 40%);">+       ast_trace(-1, "%s: Adding bundle groups (if available)\n", ast_sip_session_get_name(session));</span><br><span>     if (add_bundle_groups(session, inv->pool_prov, local)) {</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add bundled\n");</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Couldn't add bundle groups\n", ast_sip_session_get_name(session));</span><br><span>      }</span><br><span> </span><br><span>        /* Use the connection details of an available media if possible for SDP level */</span><br><span style="color: hsl(120, 100%, 40%);">+      ast_trace(-1, "%s: Copying connection details\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>    for (stream = 0; stream < local->media_count; stream++) {</span><br><span style="color: hsl(120, 100%, 40%);">+               SCOPE_ENTER(4, "%s: Processing media %d\n", ast_sip_session_get_name(session), stream);</span><br><span>            if (!local->media[stream]->conn) {</span><br><span style="color: hsl(0, 100%, 40%);">-                        continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Media %d has no connection info\n", ast_sip_session_get_name(session), stream);</span><br><span>             }</span><br><span> </span><br><span>                if (local->conn) {</span><br><span>@@ -5030,18 +5081,20 @@</span><br><span>                              !pj_strcmp(&local->conn->addr, &local->media[stream]->conn->addr)) {</span><br><span>                          local->media[stream]->conn = NULL;</span><br><span>                     }</span><br><span style="color: hsl(0, 100%, 40%);">-                       continue;</span><br><span style="color: hsl(120, 100%, 40%);">+                     SCOPE_EXIT_EXPR(continue, "%s: Media %d has good existing connection info\n", ast_sip_session_get_name(session), stream);</span><br><span>          }</span><br><span> </span><br><span>                /* This stream's connection info will serve as the connection details for SDP level */</span><br><span>           local->conn = local->media[stream]->conn;</span><br><span>           local->media[stream]->conn = NULL;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-            continue;</span><br><span style="color: hsl(120, 100%, 40%);">+             SCOPE_EXIT_EXPR(continue, "%s: Media %d reset\n", ast_sip_session_get_name(session), stream);</span><br><span>      }</span><br><span> </span><br><span>        /* If no SDP level connection details are present then create some */</span><br><span>        if (!local->conn) {</span><br><span style="color: hsl(120, 100%, 40%);">+                ast_trace(-1, "%s: Creating connection details\n", ast_sip_session_get_name(session));</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span>           local->conn = pj_pool_zalloc(inv->pool_prov, sizeof(struct pjmedia_sdp_conn));</span><br><span>                 local->conn->net_type = STR_IN;</span><br><span>                local->conn->addr_type = session->endpoint->media.rtp.ipv6 ? STR_IP6 : STR_IP4;</span><br><span>@@ -5057,31 +5110,31 @@</span><br><span>        pj_strassign(&local->origin.addr_type, &local->conn->addr_type);</span><br><span>    pj_strassign(&local->origin.addr, &local->conn->addr);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">-     SCOPE_EXIT_RTN_VALUE(local);</span><br><span style="color: hsl(120, 100%, 40%);">+end:</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_EXIT_RTN_VALUE(local, "%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static void session_inv_on_rx_offer(pjsip_inv_session *inv, const pjmedia_sdp_session *offer)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-        pjmedia_sdp_session *answer;</span><br><span>         struct ast_sip_session *session = inv->mod_data[session_module.id];</span><br><span style="color: hsl(0, 100%, 40%);">-  SCOPE_ENTER(1, "%s Inv State: %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-               pjsip_inv_state_name(inv->state));</span><br><span style="color: hsl(120, 100%, 40%);">+ pjmedia_sdp_session *answer;</span><br><span style="color: hsl(120, 100%, 40%);">+  SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (ast_shutdown_final()) {</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN("Shutting down\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_RTN("%s: Shutdown in progress\n", ast_sip_session_get_name(session));</span><br><span>   }</span><br><span> </span><br><span>        session = inv->mod_data[session_module.id];</span><br><span>       if (handle_incoming_sdp(session, offer)) {</span><br><span>           ast_sip_session_media_state_reset(session->pending_media_state);</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN("Couldn't handle sdp\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                SCOPE_EXIT_RTN("%s: handle_incoming_sdp failed\n", ast_sip_session_get_name(session));</span><br><span>     }</span><br><span> </span><br><span>        if ((answer = create_local_sdp(inv, session, offer))) {</span><br><span>              pjsip_inv_set_sdp_answer(inv, answer);</span><br><span style="color: hsl(120, 100%, 40%);">+                SCOPE_EXIT_RTN("%s: Set SDP answer\n", ast_sip_session_get_name(session));</span><br><span>         }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT_RTN("%s: create_local_sdp failed\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> #if 0</span><br><span>@@ -5093,13 +5146,12 @@</span><br><span> </span><br><span> static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t status)</span><br><span> {</span><br><span style="color: hsl(0, 100%, 40%);">-       const pjmedia_sdp_session *local, *remote;</span><br><span>   struct ast_sip_session *session = inv->mod_data[session_module.id];</span><br><span style="color: hsl(0, 100%, 40%);">-  SCOPE_ENTER(1, "%s  Inv State: %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(0, 100%, 40%);">-              pjsip_inv_state_name(inv->state));</span><br><span style="color: hsl(120, 100%, 40%);">+ const pjmedia_sdp_session *local, *remote;</span><br><span style="color: hsl(120, 100%, 40%);">+    SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));</span><br><span> </span><br><span>     if (ast_shutdown_final()) {</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN("Shutting down\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_RTN("%s: Shutdown in progress\n", ast_sip_session_get_name(session));</span><br><span>   }</span><br><span> </span><br><span>        session = inv->mod_data[session_module.id];</span><br><span>@@ -5109,7 +5161,7 @@</span><br><span>                * don't care about media updates.</span><br><span>                * Just ignore</span><br><span>                */</span><br><span style="color: hsl(0, 100%, 40%);">-             SCOPE_EXIT_RTN("No session or channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+          SCOPE_EXIT_RTN("%s: No channel or session\n", ast_sip_session_get_name(session));</span><br><span>  }</span><br><span> </span><br><span>        if (session->endpoint) {</span><br><span>@@ -5127,24 +5179,24 @@</span><br><span> </span><br><span>            if (inv->following_fork) {</span><br><span>                        if (session->endpoint->media.rtp.follow_early_media_fork) {</span><br><span style="color: hsl(0, 100%, 40%);">-                               ast_debug(3, "Following early media fork with different To tags\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                                ast_trace(-1, "%s: Following early media fork with different To tags\n", ast_sip_session_get_name(session));</span><br><span>                       } else {</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_debug(3, "Not following early media fork with different To tags\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                            ast_trace(-1, "%s: Not following early media fork with different To tags\n", ast_sip_session_get_name(session));</span><br><span>                           bail = 1;</span><br><span>                    }</span><br><span>            }</span><br><span> #ifdef HAVE_PJSIP_INV_ACCEPT_MULTIPLE_SDP_ANSWERS</span><br><span>               else if (inv->updated_sdp_answer) {</span><br><span>                       if (session->endpoint->media.rtp.accept_multiple_sdp_answers) {</span><br><span style="color: hsl(0, 100%, 40%);">-                           ast_debug(3, "Accepting updated SDP with same To tag\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                           ast_trace(-1, "%s: Accepting updated SDP with same To tag\n", ast_sip_session_get_name(session));</span><br><span>                  } else {</span><br><span style="color: hsl(0, 100%, 40%);">-                                ast_debug(3, "Ignoring updated SDP answer with same To tag\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                             ast_trace(-1, "%s: Ignoring updated SDP answer with same To tag\n", ast_sip_session_get_name(session));</span><br><span>                            bail = 1;</span><br><span>                    }</span><br><span>            }</span><br><span> #endif</span><br><span>          if (bail) {</span><br><span style="color: hsl(0, 100%, 40%);">-                     SCOPE_EXIT_RTN("Bail\n");</span><br><span style="color: hsl(120, 100%, 40%);">+                   SCOPE_EXIT_RTN("%s: Bailing\n", ast_sip_session_get_name(session));</span><br><span>                }</span><br><span>    }</span><br><span> </span><br><span>@@ -5153,14 +5205,14 @@</span><br><span>              ast_channel_hangupcause_set(session->channel, AST_CAUSE_BEARERCAPABILITY_NOTAVAIL);</span><br><span>               ast_set_hangupsource(session->channel, ast_channel_name(session->channel), 0);</span><br><span>                 ast_queue_hangup(session->channel);</span><br><span style="color: hsl(0, 100%, 40%);">-          SCOPE_EXIT_RTN("Couldn't get active local\n");return;</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_RTN("%s: Couldn't get active or local or remote negotiator.  Hanging up\n", ast_sip_session_get_name(session));</span><br><span>     }</span><br><span> </span><br><span>        if (handle_negotiated_sdp(session, local, remote)) {</span><br><span>                 ast_sip_session_media_state_reset(session->pending_media_state);</span><br><span style="color: hsl(120, 100%, 40%);">+           SCOPE_EXIT_RTN("%s: handle_negotiated_sdp failed.  Resetting pending media state\n", ast_sip_session_get_name(session));</span><br><span>   }</span><br><span style="color: hsl(0, 100%, 40%);">-</span><br><span style="color: hsl(0, 100%, 40%);">-       SCOPE_EXIT_RTN();</span><br><span style="color: hsl(120, 100%, 40%);">+     SCOPE_EXIT_RTN("%s\n", ast_sip_session_get_name(session));</span><br><span> }</span><br><span> </span><br><span> static pjsip_redirect_op session_inv_on_redirected(pjsip_inv_session *inv, const pjsip_uri *target, const pjsip_event *e)</span><br><span>@@ -5230,6 +5282,8 @@</span><br><span>   struct ast_sip_nat_hook *hook = ast_sip_mod_data_get(</span><br><span>                tdata->mod_data, session_module.id, MOD_DATA_NAT_HOOK);</span><br><span>   struct pjmedia_sdp_session *sdp;</span><br><span style="color: hsl(120, 100%, 40%);">+      pjsip_dialog *dlg = pjsip_tdata_get_dlg(tdata);</span><br><span style="color: hsl(120, 100%, 40%);">+       struct ast_sip_session *session = dlg ? ast_sip_dialog_get_session(dlg) : NULL;</span><br><span>      int stream;</span><br><span> </span><br><span>      /* SDP produced by us directly will never be multipart */</span><br><span>@@ -5253,8 +5307,9 @@</span><br><span>             * outgoing session IP is local. If it is, we'll do</span><br><span>               * rewriting. No localnet configured? Always rewrite. */</span><br><span>             if (ast_sip_transport_is_local(transport_state, &our_sdp_addr) || !transport_state->localnet) {</span><br><span style="color: hsl(0, 100%, 40%);">-                  ast_debug(5, "Setting external media address to %s\n", ast_sockaddr_stringify_addr_remote(&transport_state->external_media_address));</span><br><span style="color: hsl(0, 100%, 40%);">-                  pj_strdup2(tdata->pool, &sdp->conn->addr, ast_sockaddr_stringify_addr_remote(&transport_state->external_media_address));</span><br><span style="color: hsl(120, 100%, 40%);">+                  ast_debug(5, "%s: Setting external media address to %s\n", ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                               ast_sockaddr_stringify_host(&transport_state->external_media_address));</span><br><span style="color: hsl(120, 100%, 40%);">+                        pj_strdup2(tdata->pool, &sdp->conn->addr, ast_sockaddr_stringify_host(&transport_state->external_media_address));</span><br><span>                        pj_strassign(&sdp->origin.addr, &sdp->conn->addr);</span><br><span>          }</span><br><span>    }</span><br><span>@@ -5270,7 +5325,8 @@</span><br><span> </span><br><span>                handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);</span><br><span>               if (!handler_list) {</span><br><span style="color: hsl(0, 100%, 40%);">-                    ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);</span><br><span style="color: hsl(120, 100%, 40%);">+                    ast_debug(4, "%s: No registered SDP handlers for media type '%s'\n",  ast_sip_session_get_name(session),</span><br><span style="color: hsl(120, 100%, 40%);">+                            media);</span><br><span>                      continue;</span><br><span>            }</span><br><span>            AST_LIST_TRAVERSE(&handler_list->list, handler, next) {</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.asterisk.org/c/asterisk/+/14892">change 14892</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.asterisk.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.asterisk.org/c/asterisk/+/14892"/><meta itemprop="name" content="View Change"/></div></div>

<div style="display:none"> Gerrit-Project: asterisk </div>
<div style="display:none"> Gerrit-Branch: 18 </div>
<div style="display:none"> Gerrit-Change-Id: I06af034d1ff3ea1feb56596fd7bd6d7939dfdcc3 </div>
<div style="display:none"> Gerrit-Change-Number: 14892 </div>
<div style="display:none"> Gerrit-PatchSet: 1 </div>
<div style="display:none"> Gerrit-Owner: George Joseph <gjoseph@digium.com> </div>
<div style="display:none"> Gerrit-MessageType: newchange </div>