979966 - Need better r_log diagnostics when no candidate pairs exist for a stream

Status: RESOLVED FIXED

(Core :: WebRTC: Networking, defect, P4)

Description

[Byron Campen [:bwc]]

We've observed an intermittent mochitest failure (bug 977944) that resulted from the lack of any candidate pairs, but the logging gives us no indication whether this was due to the lack of local or remote candidates. We probably want to dump the local and remote candidates when this happens, so we at least know what we're missing. This may end up being related to bug 833043.

Comment 1

[Byron Campen [:bwc]]

I'm seeing some *_dump_state functions that seem to gathering dust; I think that fixing them up is going to be the best approach here.

Comment 2

[Byron Campen [:bwc]]

Attachment: Log some diagnostic information when we have no candidate pairs on a stream when starting checks.

Initial cut.

Comment 3

[Eric Rescorla (:ekr)]

Comment on attachment 8386490 [details] [diff] [review]
Log some diagnostic information when we have no candidate pairs on a stream when starting checks.

Review of attachment 8386490 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/mtransport/third_party/nICEr/src/ice/ice_component.c
@@ +1085,5 @@
>      return(_status);
>    }
> +
> +
> +int nr_ice_component_dump_state(nr_ice_component *comp)

Can we rename this something that's more indicative that it's loud?

Dump sounds like debugging.

@@ +1087,5 @@
> +
> +
> +int nr_ice_component_dump_state(nr_ice_component *comp)
> +  {
> +    nr_ice_candidate *cand;

Whitesapace after this line please.

::: media/mtransport/third_party/nICEr/src/ice/ice_media_stream.c
@@ +357,5 @@
>  
>      /* Find the highest priority WAITING check and move it to RUNNING */
>      pair=TAILQ_FIRST(&stream->check_list);
> +
> +    if(!pair){

This isn't correct. Chrome only trickles and we probably will n future.

@@ +389,5 @@
>        nr_ice_candidate_pair_start(pair->pctx,pair); /* Ignore failures */
>        NR_ASYNC_TIMER_SET(timer_val,nr_ice_media_stream_check_timer_cb,cb_arg,&stream->timer);
>      }
>      else {
> +      r_log(LOG_ICE,LOG_INFO,"ICE-PEER(%s): no FROZEN/WAITING pairs for %s",stream->pctx->label,stream->label);

for stream %s.

@@ +547,3 @@
>  
> +    if(stream->local_stream){
> +      // stream has a corresponding local_stream

Please convert to C-style comments. I know this is a big in the original.

@@ +547,4 @@
>  
> +    if(stream->local_stream){
> +      // stream has a corresponding local_stream
> +      nr_ice_media_stream_dump_state(stream->local_stream->pctx,stream->local_stream,0);

You are passing a null file pointer, so this doesn't do anything, right?

@@ +547,5 @@
>  
> +    if(stream->local_stream){
> +      // stream has a corresponding local_stream
> +      nr_ice_media_stream_dump_state(stream->local_stream->pctx,stream->local_stream,0);
> +      r_log(LOG_ICE,LOG_WARNING,"ICE-PEER(%s)/STREAM(%s): state dump", stream->pctx->label, stream->label);

This seems like it could be a clearer message.

Comment 4

[Byron Campen [:bwc]]

Comment on attachment 8386490 [details] [diff] [review]
Log some diagnostic information when we have no candidate pairs on a stream when starting checks.

Review of attachment 8386490 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/mtransport/third_party/nICEr/src/ice/ice_component.c
@@ +1085,5 @@
>      return(_status);
>    }
> +
> +
> +int nr_ice_component_dump_state(nr_ice_component *comp)

How about "s/dump_state/postmortem_log/"?

::: media/mtransport/third_party/nICEr/src/ice/ice_media_stream.c
@@ +357,5 @@
>  
>      /* Find the highest priority WAITING check and move it to RUNNING */
>      pair=TAILQ_FIRST(&stream->check_list);
> +
> +    if(!pair){

Hmm. Then we'll have to completely change when we dump. However, it seems reasonable to do this when the stream fails, and that will be more useful than just catching this specific problem.

@@ +547,4 @@
>  
> +    if(stream->local_stream){
> +      // stream has a corresponding local_stream
> +      nr_ice_media_stream_dump_state(stream->local_stream->pctx,stream->local_stream,0);

This function (and nr_ice_candidate_pair_dump_state) never used that param anyhow; they contained some commented-out logging statements but did nothing. I can prune out the dead code if you like.

@@ +547,5 @@
>  
> +    if(stream->local_stream){
> +      // stream has a corresponding local_stream
> +      nr_ice_media_stream_dump_state(stream->local_stream->pctx,stream->local_stream,0);
> +      r_log(LOG_ICE,LOG_WARNING,"ICE-PEER(%s)/STREAM(%s): state dump", stream->pctx->label, stream->label);

How about "begin state dump"? This is only there to explain what the following output is all about.

Comment 5

[Byron Campen [:bwc]]

Attachment: Dump diagnostic information when an ICE media stream fails.

Incorporate some review feedback, and perform a postmortem dump whenever a media stream fails. Clean up some dead code, with a relatively light touch. Might be useful to scrub harder.

Comment 6

[Byron Campen [:bwc]]

Comment on attachment 8402950 [details] [diff] [review]
Dump diagnostic information when an ICE media stream fails.

Review of attachment 8402950 [details] [diff] [review]:
-----------------------------------------------------------------

Actually, I'm seeing output that doesn't make sense. Need to dig into it and fix.

Comment 7

[Byron Campen [:bwc]]

Attachment: Dump diagnostic information when an ICE media stream fails.Bug 979966: Dump diagnostic information when an ICE media stream fails.

Remove some redundant information from the component log dump.

Comment 8

[Byron Campen [:bwc]]

Attachment: Dump diagnostic information when an ICE media stream fails.

Remove a hunk that I decided we didn't need, but missed on the last export. Also, fix commit message.

Comment 9

[Eric Rescorla (:ekr)]

Comment on attachment 8404120 [details] [diff] [review]
Dump diagnostic information when an ICE media stream fails.

Review of attachment 8404120 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/mtransport/third_party/nICEr/src/ice/ice_component.c
@@ +1089,5 @@
> +int nr_ice_component_postmortem_log(nr_ice_component *comp)
> +  {
> +    nr_ice_candidate *cand;
> +
> +    if (comp->local_component) {

This could use a comment to explain what is going on.
Took me a minute to realize that you were using the existence of a local component to indicate that it was a remote componet.

::: media/mtransport/third_party/nICEr/src/ice/ice_media_stream.c
@@ +537,4 @@
>  
> +    if(stream->local_stream){
> +      /* stream has a corresponding local_stream */
> +      nr_ice_media_stream_postmortem_log(stream->local_stream->pctx,stream->local_stream);

Why are you not checking for errors here?

@@ +552,4 @@
>  
> +    comp=STAILQ_FIRST(&stream->components);
> +    while(comp){
> +      nr_ice_component_postmortem_log(comp);

Error checks.

::: media/mtransport/third_party/nICEr/src/ice/ice_peer_ctx.h
@@ +77,5 @@
>  int nr_ice_peer_ctx_pair_candidates(nr_ice_peer_ctx *pctx);
>  int nr_ice_peer_ctx_parse_global_attributes(nr_ice_peer_ctx *pctx, char **attrs, int attr_ct);
>  int nr_ice_peer_ctx_start_checks(nr_ice_peer_ctx *pctx);
>  int nr_ice_peer_ctx_start_checks2(nr_ice_peer_ctx *pctx, int allow_non_first);
> +int nr_ice_peer_ctx_postmortem_log(nr_ice_peer_ctx *pctx);

Is this only called on failure? I thought it could be called anywhere.

Suggest instead we just call it dump and provide a log level argument

Comment 10

[Bulk Bug Changes for mreavy's org]

Mass change P3->P4 to align with new Mozilla triage process.

Comment 11

[Byron Campen [:bwc]]

Attachment: Bug 979966: Dump diagnostic information when an ICE stream fails.

Comment 12

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=53980b5582c6a0cf7cf53f2e38b043168bd1cb67

Comment 13

[Byron Campen [:bwc]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f1660ae4e796

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f9252c02242c
Dump diagnostic information when an ICE stream fails. r=mjf

Comment 15

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/f9252c02242c