[asterisk-bugs] [JIRA] (ASTERISK-25449) main/sched: Regression introduced by 5c713fdf18f causes erroneous duplicate RTCP messages; other potential scheduling issues in chan_sip/chan_skinny

Dirk Wendland (JIRA) noreply at issues.asterisk.org
Tue Oct 27 04:29:33 CDT 2015 

    [ https://issues.asterisk.org/jira/browse/ASTERISK-25449?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=228015#comment-228015 ] 

Dirk Wendland edited comment on ASTERISK-25449 at 10/27/15 4:28 AM:
--------------------------------------------------------------------

This is Gerald Schnabel writing because JIRA doesn't let me log in with my account even after several password resets. So I'm writing this with the account of my colleague Dirk.

----

Commit 5c713fdf18f _scheduler: Use queue for allocating sched IDs_ (still) breaks chan_sip.c in asterisk 11.20.0!

Some functions that handle REGISTER expiry do not and can not handle scheduler ID 0.

In {{parse_register_contact()}} {{peer->expire}} is set to the scheduler ID (return value of {{ast_sched_add()}}).

scheduler ID 0 is *not* handled in:

* sip_unregister(): {{peer->expire > 0}}
* complete_sip_registered_peer(): {{peer->expire > 0}}
* set_peer_defaults():

Especially set_peer_defaults() breaks REGISTER expiry threads if doing a _sip reload_ when an expiry thread with scheduler ID 0 exists!
If {{peer->expire}} is 0 all expiry fields are set to -1. ("Don't reset expire or port time during reload if we have an active registration").
Peers then regularly get unregistered.

Before _sip reload_:

{noformat}
[Oct 23 10:14:58] DEBUG[23308] sched.c: Asterisk Schedule Dump (4 in Q, 182 Total, 4 Cache, 8 high-water)
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
[Oct 23 10:14:58] DEBUG[23308] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[Oct 23 10:14:58] DEBUG[23308] sched.c: +-----+-----------------+-----------------+-----------------+
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0000 | 0x7fb01b3bed94  | 0x336bb58       | 000011 : 574414 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0002 | 0x7fb01b3bed94  | 0x3362f08       | 003563 : 231276 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0011 | 0x7fb01b3841c1  | 0x7fb03c10b978  | 000017 : 301530 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0008 | 0x7fb01b3841c1  | 0x7fb03c198f08  | 003564 : 124105 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
{noformat}

After _sip reload_: REGISTER expiry thread with ID 0000 is duplicated (-> ID 0009), REGISTER expiry thread with ID 0000 regularly unregisters peer:

{noformat}
[Oct 23 10:14:58] DEBUG[23308] sched.c: Asterisk Schedule Dump (5 in Q, 183 Total, 3 Cache, 8 high-water)
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
[Oct 23 10:14:58] DEBUG[23308] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[Oct 23 10:14:58] DEBUG[23308] sched.c: +-----+-----------------+-----------------+-----------------+
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0000 | 0x7fb01b3bed94  | 0x336bb58       | 000011 : 573282 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0009 | 0x7fb01b3bed94  | 0x336bb58       | 000069 : 999977 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0011 | 0x7fb01b3841c1  | 0x7fb03c10b978  | 000017 : 300398 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0008 | 0x7fb01b3841c1  | 0x7fb03c198f08  | 003564 : 122973 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0002 | 0x7fb01b3bed94  | 0x3362f08       | 003563 : 230144 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
{noformat}



was (Author: kesselklopfer79):
Commit 5c713fdf18f _scheduler: Use queue for allocating sched IDs_ (still) breaks chan_sip.c in asterisk 11.20.0!

Some functions that handle REGISTER expiry do not and can not handle scheduler ID 0.

In {{parse_register_contact()}} {{peer->expire}} is set to the scheduler ID (return value of {{ast_sched_add()}}).

scheduler ID 0 is *not* handled in:

* sip_unregister(): {{peer->expire > 0}}
* complete_sip_registered_peer(): {{peer->expire > 0}}
* set_peer_defaults():

Especially set_peer_defaults() breaks REGISTER expiry threads if doing a _sip reload_ when an expiry thread with scheduler ID 0 exists!
If {{peer->expire}} is 0 all expiry fields are set to -1. ("Don't reset expire or port time during reload if we have an active registration").
Peers then regularly get unregistered.

Before _sip reload_:

{noformat}
[Oct 23 10:14:58] DEBUG[23308] sched.c: Asterisk Schedule Dump (4 in Q, 182 Total, 4 Cache, 8 high-water)
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
[Oct 23 10:14:58] DEBUG[23308] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[Oct 23 10:14:58] DEBUG[23308] sched.c: +-----+-----------------+-----------------+-----------------+
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0000 | 0x7fb01b3bed94  | 0x336bb58       | 000011 : 574414 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0002 | 0x7fb01b3bed94  | 0x3362f08       | 003563 : 231276 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0011 | 0x7fb01b3841c1  | 0x7fb03c10b978  | 000017 : 301530 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0008 | 0x7fb01b3841c1  | 0x7fb03c198f08  | 003564 : 124105 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
{noformat}

After _sip reload_: REGISTER expiry thread with ID 0000 is duplicated (-> ID 0009), REGISTER expiry thread with ID 0000 regularly unregisters peer:

{noformat}
[Oct 23 10:14:58] DEBUG[23308] sched.c: Asterisk Schedule Dump (5 in Q, 183 Total, 3 Cache, 8 high-water)
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
[Oct 23 10:14:58] DEBUG[23308] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[Oct 23 10:14:58] DEBUG[23308] sched.c: +-----+-----------------+-----------------+-----------------+
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0000 | 0x7fb01b3bed94  | 0x336bb58       | 000011 : 573282 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0009 | 0x7fb01b3bed94  | 0x336bb58       | 000069 : 999977 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0011 | 0x7fb01b3841c1  | 0x7fb03c10b978  | 000017 : 300398 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0008 | 0x7fb01b3841c1  | 0x7fb03c198f08  | 003564 : 122973 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: |0002 | 0x7fb01b3bed94  | 0x3362f08       | 003563 : 230144 |
[Oct 23 10:14:58] DEBUG[23308] sched.c: =============================================================
{noformat}


> main/sched: Regression introduced by 5c713fdf18f causes erroneous duplicate RTCP messages; other potential scheduling issues in chan_sip/chan_skinny
> ----------------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: ASTERISK-25449
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-25449
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/General
>            Reporter: Matt Jordan
>            Severity: Blocker
>      Target Release: 11.20.0, 13.6.0
>
>
> When 5c713fdf18f was committed, it exposed several consumers of the scheduler API that were not abiding by its contract. These consumers viewed a scheduler ID of 0 as being invalid, when it is in fact a valid scheduler ID. This has different affects:
> * A scheduled item may be scheduled twice (as in the case of {{res_rtp_asterisk}})
> * A valid scheduled item may be viewed as non-existing, causing logic to fire that should not (as in the case of {{chan_sip}})
> * A valid scheduled item may be viewed as a failure



--
This message was sent by Atlassian JIRA
(v6.2#6252)

More information about the asterisk-bugs mailing list