[Home]

Summary:ASTERISK-11574: [patch] Attempted to delete nonexistent schedule entry
Reporter:Badalian Vyacheslav (slavon)Labels:
Date Opened:2008-03-04 23:32:05.000-0600Date Closed:2008-03-05 14:41:39.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) sch.patch
( 1) sch2.patch
Description:In DEBUG messages i see many messages like this:
ast_sched_del: Attempted to delete nonexistent schedule entry 0!

i look to backtrace and see this:
#0  ast_sched_del (con=0xb7629a20, id=0) at sched.c:291
#1  0xb6f970fd in __sip_reliable_xmit (p=0x8216c08, seqno=102, resp=0,
   data=0xb6795c48 "INVITE sip:6624658@87.255.0.218 SIP/2.0\r\nVia: SIP/2.0/UDP 87.255.9.250:5060;branch=z9hG4bK1abe39d1;rport\r\nMax-Forwards: 70\r\nFrom: \"4955021766\" <sip:4955021766@87.255.9.250>;tag=as745a2efb\r\nTo: <sip:66"..., len=863, fatal=1,
   sipmethod=5) at chan_sip.c:2824
#2  0xb6f9870d in send_request (p=0x8216c08, req=0xb6795a24, reliable=XMIT_CRITICAL, seqno=102) at chan_sip.c:3083
#3  0xb6fb158d in transmit_invite (p=0x8216c08, sipmethod=5, sdp=1, init=2) at chan_sip.c:8705
#4  0xb6f9d492 in sip_call (ast=0x821ad20, dest=0xb6797a78 "6624658@voip", timeout=0) at chan_sip.c:4170
ASTERISK-1  0x0808e8b9 in ast_call (chan=0x821ad20, addr=0xb6797a78 "6624658@voip", timeout=0) at channel.c:3392
ASTERISK-2  0xb749869c in dial_exec_full (chan=0x8215678, data=0xb6799eb8, peerflags=0xb6797d3c, continue_exec=0x0) at app_dial.c:1533
ASTERISK-3  0xb749b18c in dial_exec (chan=0x8215678, data=0xb6799eb8) at app_dial.c:1964
ASTERISK-4  0x080ddac6 in pbx_exec (c=0x8215678, app=0x81d2498, data=0xb6799eb8) at pbx.c:728
ASTERISK-5  0x080e2dd2 in pbx_extension_helper (c=0x8215678, con=0x0, context=0x82157fc "zap-g1-in", exten=0x821584c "6624658",
   priority=1, label=0x0, callerid=0x8211f08 "4955021766", action=E_SPAWN, found=0xb679c2fc, combined_find_spawn=1)
   at pbx.c:2699
ASTERISK-6 0x080e415a in ast_spawn_extension (c=0x8215678, context=0x82157fc "zap-g1-in", exten=0x821584c "6624658", priority=1,
   callerid=0x8211f08 "4955021766", found=0xb679c2fc, combined_find_spawn=1) at pbx.c:3190
ASTERISK-7 0x080e486a in __ast_pbx_run (c=0x8215678) at pbx.c:3289
ASTERISK-8 0x080e59f8 in pbx_thread (data=0x8215678) at pbx.c:3551
ASTERISK-9 0x0812b002 in dummy_start (data=0x8212088) at utils.c:870
ASTERISK-10 0xb7cd918b in start_thread () from /lib/libpthread.so.0
ASTERISK-11 0xb7db476e in clone () from /lib/libc.so.6

then i look to code chan_sip.c:2824 and look this macros:
AST_SCHED_REPLACE_VARIABLE(pkt->retransid, sched, siptimer_a, retrans_pkt, pkt, 1);

look up and see what pkt defined in this function, but pkt->retransid not defined.

Its bug?

Tested on last 1.4 SVN and TRUNK svn

Thanks
Comments:By: Badalian Vyacheslav (slavon) 2008-03-04 23:32:32.000-0600

Sorry. Category CORE-General... =(
By: Badalian Vyacheslav (slavon) 2008-03-05 00:49:14.000-0600

its interesting for me because i see in DEBUG and messages like this

[Mar  5 09:40:13] DEBUG[12754]: chan_sip.c:7965 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[Mar  5 09:40:13] DEBUG[12754]: chan_sip.c:7966 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1134 channel_find_locked: Failure, could not lock '0x82c2b90' after 9 retries!
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!
[Mar  5 09:40:13] DEBUG[12754]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x82c2b90'
[Mar  5 09:40:13] DEBUG[12754]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry 0!

also in code sched.c:291 next line do CRUSH and if i aright this must say that its critical error?

if its not bug - sorry, but looks fear for me =))
By: Badalian Vyacheslav (slavon) 2008-03-05 01:12:47.000-0600

i think pkt->retransid must be -1.. its say to macro AST_SCHED_REPLACE_VARIABLE what we not need to delete any element and next line (id = ast_sched_add_variable...) return normal id to packet.
By: Tilghman Lesher (tilghman) 2008-03-05 01:21:35.000-0600

It is a DEBUG message, not an ERROR or a WARNING.  The type of log message was chosen very specifically, because it is neither an ERROR nor a WARNING.  Please do not report DEBUG messages as bugs.
By: Badalian Vyacheslav (slavon) 2008-03-05 03:53:03.000-0600

i think code have defect. i write patch that fix it. Also 1 place in code need to discussion. I post patch and comment it
By: Badalian Vyacheslav (slavon) 2008-03-05 04:07:46.000-0600

Describe patch:

Macro AST_SCHED_DEL and AST_SCHED_REPLACE_VARIABLE
1. _count never be 10 and you can't do WARNING never. fix it
2. if i understand code must loop while ast_sched_del can delete id (id may be more then one?), but in code you do loop while ast_sched_del can't find id in list. great that we have _count check =) its may be forever loop. fix it.

function __sip_reliable_xmit
1. you must set pkt->retransid = -1 because not need del sched or use ast_sched_add_variable (not AST_SCHED_REPLACE_VARIABLE)


By: Badalian Vyacheslav (slavon) 2008-03-05 04:13:12.000-0600

to discussion:

macro AST_SCHED_REPLACE_VARIABLE and AST_SCHED_DEL try del sched while ast_sched_del not returned -1 (not found). Looks end of function ast_sched_del:

       if (!s) {
               ast_debug(1, "Attempted to delete nonexistent schedule entry %d!\n", id);
#ifdef DO_CRASH
               CRASH;
#endif
               return -1;
       }

1. if use macro AST_SCHED_DEL or AST_SCHED_REPLACE_VARIABLE and defined DO_CRASH system all time do CRASH - wrong.
2. if use macro AST_SCHED_DEL or AST_SCHED_REPLACE_VARIABLE you post confused debug message. Macro may normal delete ID but next try not found it. Need to discussion and fix please.

thanks
slavon
By: Badalian Vyacheslav (slavon) 2008-03-05 05:42:17.000-0600

i retest value of _count

1.) while (c++ < 10); // c = 11 - wrong
2.) while (c++ <= 10); // c = 12 - wrong
3.) while (++c < 10); // c = 10 - ok and warning is showed

i repost patch


By: Digium Subversion (svnbot) 2008-03-05 09:13:36.000-0600

Repository: asterisk
Revision: 106015

U   branches/1.4/channels/chan_sip.c
U   branches/1.4/include/asterisk/sched.h

------------------------------------------------------------------------
r106015 | tilghman | 2008-03-05 09:13:29 -0600 (Wed, 05 Mar 2008) | 7 lines

Correctly initialize retransid in SIP, and ensure that the warning when failing to delete a schedule entry can actually hit the log.
(closes issue ASTERISK-11574)
Reported by: slavon
Patches:
      sch2.patch uploaded by slavon (license 288)
(Patch slightly modified by me)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=106015
By: Digium Subversion (svnbot) 2008-03-05 09:20:01.000-0600

Repository: asterisk
Revision: 106036

_U  trunk/
U   trunk/channels/chan_sip.c
U   trunk/include/asterisk/sched.h

------------------------------------------------------------------------
r106036 | tilghman | 2008-03-05 09:19:55 -0600 (Wed, 05 Mar 2008) | 15 lines

Merged revisions 106015 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r106015 | tilghman | 2008-03-05 09:17:16 -0600 (Wed, 05 Mar 2008) | 7 lines

Correctly initialize retransid in SIP, and ensure that the warning when failing to delete a schedule entry can actually hit the log.
(closes issue ASTERISK-11574)
Reported by: slavon
Patches:
      sch2.patch uploaded by slavon (license 288)
(Patch slightly modified by me)

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=106036
By: Digium Subversion (svnbot) 2008-03-05 09:27:50.000-0600

Repository: asterisk
Revision: 106037

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c
U   branches/1.6.0/include/asterisk/sched.h

------------------------------------------------------------------------
r106037 | tilghman | 2008-03-05 09:27:43 -0600 (Wed, 05 Mar 2008) | 23 lines

Merged revisions 106036 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r106036 | tilghman | 2008-03-05 09:23:32 -0600 (Wed, 05 Mar 2008) | 15 lines

Merged revisions 106015 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r106015 | tilghman | 2008-03-05 09:17:16 -0600 (Wed, 05 Mar 2008) | 7 lines

Correctly initialize retransid in SIP, and ensure that the warning when failing to delete a schedule entry can actually hit the log.
(closes issue ASTERISK-11574)
Reported by: slavon
Patches:
      sch2.patch uploaded by slavon (license 288)
(Patch slightly modified by me)

........

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=106037
By: Badalian Vyacheslav (slavon) 2008-03-05 10:09:17.000-0600

sorry but i think that check in while must be "!ast_sched_del(sched, id)" or "ast_sched_del(sched, id) == 0" because return -1 (not found) is TRUE and if you try delete not exists element its try do this 10 times. if you check it for 0 (found and succes deleted) FALSE you try delete all elements that have some id.
By: Tilghman Lesher (tilghman) 2008-03-05 10:23:00.000-0600

No, you only want to retry when deleting a schedule entry FAILS.  If deleting SUCCEEDS, then the zero response code will cause the while to fail out and the second if won't succeed.  The only time you want the warning printed is when you cannot delete the schedule ID after 10 retries.  As soon as the deletion succeeds, you do not want to proceed any further.
By: Badalian Vyacheslav (slavon) 2008-03-05 10:24:42.000-0600

i understand. sorry and thanks =)


By: Digium Subversion (svnbot) 2008-03-05 13:40:29.000-0600

Repository: asterisk
Revision: 106172

_U  team/murf/sched-rbtree/
U   team/murf/sched-rbtree/CHANGES
U   team/murf/sched-rbtree/UPGRADE.txt
U   team/murf/sched-rbtree/apps/app_amd.c
U   team/murf/sched-rbtree/apps/app_dial.c
U   team/murf/sched-rbtree/apps/app_followme.c
U   team/murf/sched-rbtree/apps/app_meetme.c
U   team/murf/sched-rbtree/apps/app_minivm.c
U   team/murf/sched-rbtree/apps/app_record.c
U   team/murf/sched-rbtree/apps/app_talkdetect.c
U   team/murf/sched-rbtree/apps/app_voicemail.c
U   team/murf/sched-rbtree/apps/app_waitforsilence.c
U   team/murf/sched-rbtree/channels/chan_sip.c
U   team/murf/sched-rbtree/channels/chan_zap.c
A   team/murf/sched-rbtree/configs/dsp.conf.sample
U   team/murf/sched-rbtree/include/asterisk/dsp.h
U   team/murf/sched-rbtree/include/asterisk/sched.h
U   team/murf/sched-rbtree/main/app.c
U   team/murf/sched-rbtree/main/asterisk.c
U   team/murf/sched-rbtree/main/dsp.c
U   team/murf/sched-rbtree/main/loader.c
U   team/murf/sched-rbtree/res/res_agi.c

------------------------------------------------------------------------
r106172 | murf | 2008-03-05 13:40:24 -0600 (Wed, 05 Mar 2008) | 57 lines

Merged revisions 106003-106170 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r106036 | tilghman | 2008-03-05 08:23:32 -0700 (Wed, 05 Mar 2008) | 15 lines
 
 Merged revisions 106015 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
 r106015 | tilghman | 2008-03-05 09:17:16 -0600 (Wed, 05 Mar 2008) | 7 lines
 
 Correctly initialize retransid in SIP, and ensure that the warning when failing to delete a schedule entry can actually hit the log.
 (closes issue ASTERISK-11574)
  Reported by: slavon
  Patches:
        sch2.patch uploaded by slavon (license 288)
 (Patch slightly modified by me)
 
 ........
................
 r106040 | kpfleming | 2008-03-05 08:40:40 -0700 (Wed, 05 Mar 2008) | 15 lines
 
 Merged revisions 106038 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
 r106038 | kpfleming | 2008-03-05 09:32:35 -0600 (Wed, 05 Mar 2008) | 7 lines
 
 when a PRI call must be moved to a different B channel at the request of the other endpoint, ensure that any DSP active on the original channel is moved to the new one
 
 (closes issue ASTERISK-11370)
 Reported by: mavetju
 Tested by: mavetju
 
 
 ........
................
 r106072 | tilghman | 2008-03-05 09:23:44 -0700 (Wed, 05 Mar 2008) | 7 lines
 
 Create a centralized configuration option for silencethreshold
 (closes issue ASTERISK-10755)
  Reported by: philipps
  Patches:
        20080218__bug11236.diff.txt uploaded by Corydon76 (license 14)
  Tested by: philipps
................
 r106110 | file | 2008-03-05 09:39:22 -0700 (Wed, 05 Mar 2008) | 2 lines
 
 Fix code up to what it was meant to be.
................
 r106139 | tilghman | 2008-03-05 10:40:42 -0700 (Wed, 05 Mar 2008) | 3 lines
 
 Should check these values for non-NULL before scanning.
 (Closes issue ASTERISK-11580)
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=106172
By: Digium Subversion (svnbot) 2008-03-05 14:41:39.000-0600

Repository: asterisk
Revision: 106177

_U  team/murf/bug11210/
U   team/murf/bug11210/CHANGES
U   team/murf/bug11210/UPGRADE.txt
U   team/murf/bug11210/apps/app_amd.c
U   team/murf/bug11210/apps/app_dial.c
U   team/murf/bug11210/apps/app_followme.c
U   team/murf/bug11210/apps/app_meetme.c
U   team/murf/bug11210/apps/app_minivm.c
U   team/murf/bug11210/apps/app_record.c
U   team/murf/bug11210/apps/app_talkdetect.c
U   team/murf/bug11210/apps/app_voicemail.c
U   team/murf/bug11210/apps/app_waitforsilence.c
U   team/murf/bug11210/channels/chan_sip.c
U   team/murf/bug11210/channels/chan_zap.c
A   team/murf/bug11210/configs/dsp.conf.sample
U   team/murf/bug11210/include/asterisk/dsp.h
U   team/murf/bug11210/include/asterisk/sched.h
U   team/murf/bug11210/main/app.c
U   team/murf/bug11210/main/asterisk.c
U   team/murf/bug11210/main/dsp.c
U   team/murf/bug11210/main/loader.c
U   team/murf/bug11210/res/res_agi.c

------------------------------------------------------------------------
r106177 | murf | 2008-03-05 14:41:31 -0600 (Wed, 05 Mar 2008) | 57 lines

Merged revisions 106001-106176 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r106036 | tilghman | 2008-03-05 08:23:32 -0700 (Wed, 05 Mar 2008) | 15 lines
 
 Merged revisions 106015 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
 r106015 | tilghman | 2008-03-05 09:17:16 -0600 (Wed, 05 Mar 2008) | 7 lines
 
 Correctly initialize retransid in SIP, and ensure that the warning when failing to delete a schedule entry can actually hit the log.
 (closes issue ASTERISK-11574)
  Reported by: slavon
  Patches:
        sch2.patch uploaded by slavon (license 288)
 (Patch slightly modified by me)
 
 ........
................
 r106040 | kpfleming | 2008-03-05 08:40:40 -0700 (Wed, 05 Mar 2008) | 15 lines
 
 Merged revisions 106038 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
 r106038 | kpfleming | 2008-03-05 09:32:35 -0600 (Wed, 05 Mar 2008) | 7 lines
 
 when a PRI call must be moved to a different B channel at the request of the other endpoint, ensure that any DSP active on the original channel is moved to the new one
 
 (closes issue ASTERISK-11370)
 Reported by: mavetju
 Tested by: mavetju
 
 
 ........
................
 r106072 | tilghman | 2008-03-05 09:23:44 -0700 (Wed, 05 Mar 2008) | 7 lines
 
 Create a centralized configuration option for silencethreshold
 (closes issue ASTERISK-10755)
  Reported by: philipps
  Patches:
        20080218__bug11236.diff.txt uploaded by Corydon76 (license 14)
  Tested by: philipps
................
 r106110 | file | 2008-03-05 09:39:22 -0700 (Wed, 05 Mar 2008) | 2 lines
 
 Fix code up to what it was meant to be.
................
 r106139 | tilghman | 2008-03-05 10:40:42 -0700 (Wed, 05 Mar 2008) | 3 lines
 
 Should check these values for non-NULL before scanning.
 (Closes issue ASTERISK-11580)
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=106177