Sip notifications slow since upgrade to 1.4.21.2 from 1.4.18

Hi All,
I’m having a problem with sip notifications for the busy lamps on reception phones.

In my asterisk install I have a small office with 20-30 endpoints. The phone system has 4 inbound PSTN lines handled by a 4 port Sangoma card. A receptionist deals with all inbound calls and usually parks them and then calls the users to let them know about the call. In this situation the receptionist has an extension block on their Snom 320 which has lots of BLF to show who is busy and whether calls are parked or not.
This was working fine while I was using asterisk 1.4.18 , but recently I upgrade to 1.4.21.2 and also added a module called func_devstate to allow me to also light up a lamp to tell the receptionist that they had put the phone system on ring around ( rings all endpoints) .
See svncommunity.digium.com/view/rus … state-1.4/
Since I have upgrade I have had a problem with sip notifications being slow.
Some times the notifications happen normally, but at least once every day the system get into a state where notifications are lagged and can take up to 1-2 minutes, so when reception parks a call normally she sees a 301 blf lit up if the call is parked on 301 or 303 is lit up if the call is parked on 303. But since the change this can be very slow to update sometime and it means she does not know where the call is parked.
I have included some of my dial plan below and the log of two calls, the first is when things are normal and the last is when the notifications are slow.

Does anyone have any suggestions for troubleshooting this one?
Regards
Albert

/* DIAL PLAN- extensions .conf */
autofallthrough=yes
[globals]
static=yes
writeprotect=no
clearglobavars=no
PSTN1=Zap/1
PSTN2=Zap/2
PSTN3=Zap/3
PSTN4=Zap/4
RECEPTION=SIP/510&SIP/515
RingAround=ON
ICMLOCAL1=SIP/5296
LINE_20008=SIP/20008&SIP/20008b
LINE_60146=SIP/60146&SIP/60146b
LINE_22186=SIP/22186&SIP/22186b
LINE_22089=SIP/22089&SIP/22089b
LINE_22897=SIP/22897&SIP/22897b
LINE_22651=SIP/22651&SIP/22651b
LINE_63001=SIP/63001&SIP/63001b
ICMLOCAL=SIP/510&SIP/512&SIP/513&SIP/514&SIP/515&SIP/516&SIP/518&SIP/521&SIP/522&SIP/523&SIP/524e&SIP/526&SIP/528&SIP/529&SIP/531&SIP/533&SIP/535&SIP/536&SIP/538&SIP/539&SIP/544&SIP/547
ICMLOCAL_E=SIP/510&SIP/512e&SIP/513e&SIP/514e&SIP/515&SIP/516&SIP/518e&SIP/521e&SIP/522e&SIP/523e&SIP/524e&SIP/526e&SIP/528e&SIP/529e&SIP/531e&SIP/533e&SIP/535e&SIP/536e&SIP/538e&SIP/539e&SIP/544e&SIP/547e

[default]
[sip]

[sip-icmlocal]
include => outgoingpstn
include => speeddials
include => conference
include => parkedcalls
include => parkedfeat
include => 4kvoicemail
include => icmextensions
include => paging
include => callmanagement
include => emergencycalls

[PSTN1]
exten => s,1,Answer
exten => s,2,NoOp(${RingAround})
exten => s,3,GotoIf($[${RingAround} = On]?PSTN1,s,7|PSTN1,s,4)
exten => s,4,NoOp(${RingAround})
exten => s,5,Dial(${LINE_22897},60,TtWwKk)
;exten => s,5,Dial(SIP/22897a,10,TtWwKk) change the priorities
exten => s,6,Hangup
exten => s,7,NoOp(${RingAround})
exten => s,8,Dial(${ICMLOCAL_E},40,TtWwKk)
exten => s,9,Hangup
;exten => s,n,Dial(${LINE_22897},20,TtWwKk)
;exten => s,n,Dial(${ICMLOCAL_E},25,TtWwKk}
;exten => s,n,Hangup

[PSTN2]
exten => s,1,Answer
exten => s,2,NoOp(${RingAround})
exten => s,3,GotoIf($[${RingAround} = On]?PSTN2,s,7|PSTN2,s,4)
exten => s,4,NoOp(${RingAround})
exten => s,5,Dial(${LINE_22651},60,TtWwKk)
;exten => s,5,Dial(SIP/22651a,10,TtWwKk) change the priorities
exten => s,6,Hangup
exten => s,7,NoOp(${RingAround})
exten => s,8,Dial(${ICMLOCAL_E},40,TtWwKk)
exten => s,9,Hangup

;exten => s,n,NoOp
;exten => s,n,Dial(${LINE_22651},20,TtWwKk)
;exten => s,n,Dial(${ICMLOCAL_E},25,TtWwKk}
;exten => s,n,Hangup

[PSTN3]
exten => s,1,Answer
exten => s,2,NoOp(${RingAround})
exten => s,3,GotoIf($[${RingAround} = On]?PSTN3,s,7|PSTN3,s,4)
exten => s,4,NoOp(${RingAround})
exten => s,5,Dial(${LINE_22089},60,TtWwKk)
;exten => s,5,Dial(SIP/22089a,10,TtWwKk) change the priorities
exten => s,6,Hangup
exten => s,7,NoOp(${RingAround})
exten => s,8,Dial(${ICMLOCAL_E},40,TtWwKk)
exten => s,9,Hangup

;exten => s,n(open),Verbose(incomming call from pstn - Callerid = ${CALLERID})
;exten => s,n,Dial(${LINE_22089},20,TtWwKk)
;exten => s,n,Dial(${ICMLOCAL_E},25,TtWwKk}
;exten => s,n,Hangup

[PSTN4]

exten => s,1,Answer
exten => s,2,NoOp(${RingAround})
exten => s,3,GotoIf($[${RingAround} = On]?PSTN4,s,7|PSTN4,s,4)
exten => s,4,NoOp(${RingAround})
exten => s,5,Dial(${LINE_22186},60,TtWwKk)
;exten => s,5,Dial(SIP/22651a,10,TtWwKk) change the priorities
exten => s,6,Hangup
exten => s,7,NoOp(${RingAround})
exten => s,8,Dial(${ICMLOCAL_E},40,TtWwKk)
exten => s,9,Hangup

;exten => s,n(open),Verbose(incomming call from pstn - Callerid = ${CALLERID})
;exten => s,n,Dial(${LINE_22186},20,TtWwKk)
;exten => s,n,Dial(${ICMLOCAL_E},15,TtWwKk}
;exten => s,n,Hangup

[macro-fastbusy]
exten => s,1,Answer
exten => s,2,Wait 1
exten => s,3,Playback(/toddsounds/thnk-u-for-patience)
exten => s,4,Wait(30)
exten => s,5,Hangup

[macro-calluser]
exten => s,1,Dial(${ARG1},45,TtWwKk)
exten => s,n,GotoIf($["${DIALSTATUS}" = “BUSY”]?busy:unavail)
exten => s,n(unavail),Playback(/toddsounds/nbdy-avail-to-take-call)
exten => s,n,VoiceMail(${MACRO_EXTEN}@default,u)
exten => s,n,Hangup()
exten => s,n(busy),VoiceMail(${MACRO_EXTEN}@default,b)
exten => s,n,Hangup()

[4kvoicemail]
;allow users to get to voicemail main menu
exten =>4000,1,VoiceMailMain

[callpickup]
;Call Pickup this allows any phone in this context to pickup another ringing extension
; by pressing *8and the extension number .
exten => _*8X.,1,Answer
exten => _*8X.,n,Pickup(${EXTEN:2},TtWwKk)

[paging]
;paging
exten => _80,1,SIPAddHeader(Call-Info:sip:10.202.17.217;answer-after=0)
exten => _80,n,Page(${ICMLOCAL_P})
exten => _80,n,Hangup

[callmanagement]
exten => 6695,hint,Custom:RingaroundOnLamp
exten => 6695,1,Set(GLOBAL(RingAround)=On)
exten => 6695,n,Set(GLOBAL(ICMLOCAL_E)=SIP/510&SIP/512e&SIP/513e&SIP/514e&SIP/515&SIP/516&SIP/518e&SIP/521e&SIP/522e&SIP/523e&SIP/524e&SIP/526e&SIP/528e&SIP/529e&SIP/531e&SIP/533e&SIP/535e&SIP/536e&SIP/538e&SIP/539e&SIP/544e&SIP/547e)
exten => 6695,n,Playback(/icm/sounds/RingAroundOn)
exten => 6695,n,Set(DEVSTATE(Custom:RingaroundOnLamp)=INUSE)
exten => 6695,n,Set(DEVSTATE(Custom:RingaroundOffLamp)=NOT_INUSE)
exten => 6695,n,Hangup

exten => 6696,hint,Custom:RingaroundOffLamp
exten => 6696,1,Set(GLOBAL(RingAround)=Off)
exten => 6696,n,Set(GLOBAL(ICMLOCAL_E)=SIP/510&SIP/512e&SIP/513e&SIP/514e&SIP/515&SIP/516&SIP/518e&SIP/521e&SIP/522e&SIP/523e&SIP/524e&SIP/526e&SIP/528e&SIP/529e&SIP/531e&SIP/533e&SIP/535e&SIP/536e&SIP/538e&SIP/539e&SIP/544e&SIP/547e)
exten => 6696,n,Playback(/icm/sounds/RingAroundOff)
exten => 6696,n,Set(DEVSTATE(Custom:RingaroundOffLamp)=INUSE)
exten => 6696,n,Set(DEVSTATE(Custom:RingaroundOnLamp)=NOT_INUSE)
exten => 6696,n,Hangup

[icmextensions]
exten => 510,hint,SIP/510
exten => 510,1,Macro(calluser,SIP/510)

exten => 511,hint,SIP/511
exten => 511,1,Macro(calluser,SIP/511)

exten => 512,hint,SIP/512
exten => 512,1,Macro(calluser,SIP/512)

exten => 513,hint,SIP/513
exten => 513,1,Macro(calluser,SIP/513)

exten => 514,hint,SIP/514
exten => 514,1,Macro(calluser,SIP/514)

[parkedcalls]
exten => 301,1,ParkedCall(301)
exten => 301,hint,park:301@parkedfeat
exten => 302,1,ParkedCall(302)
exten => 302,hint,park:302@parkedfeat
exten => 303,1,ParkedCall(303)
exten => 303,hint,park:303@parkedfeat
exten => 304,1,ParkedCall(304)
exten => 304,hint,park:304@parkedfeat
exten => 305,1,ParkedCall(305)
exten => 305,hint,park:305@parkedfeat
exten => 306,1,ParkedCall(306)
exten => 306,hint,park:306@parkedfeat
/* DIAL PLAN- extensions .conf */

/* log of Call parking normally /
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Starting simple switch on ‘Zap/1-1’
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Executing [s@PSTN1:1] Answer(“Zap/1-1”, “”) in new stack
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Executing [s@PSTN1:2] NoOp(“Zap/1-1”, “Off”) in new stack
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Executing [s@PSTN1:3] GotoIf(“Zap/1-1”, “0?PSTN1|s|7|PSTN1|s|4”) in new stack
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Executing [s@PSTN1:4] NoOp(“Zap/1-1”, “Off”) in new stack
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Executing [s@PSTN1:5] Dial(“Zap/1-1”, “SIP/22897&SIP/22897b|60|TtWwKk”) in new stack
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Called 22897
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – Called 22897b
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – SIP/22897b-16b43c30 is ringing
[Oct 14 11:25:01] VERBOSE[6713] logger.c: – SIP/22897-16b92410 is ringing
[Oct 14 11:25:02] VERBOSE[6713] logger.c: – SIP/22897b-16b43c30 is ringing
[Oct 14 11:25:02] VERBOSE[6713] logger.c: – SIP/22897-16b92410 is ringing
[Oct 14 11:25:03] VERBOSE[6713] logger.c: – SIP/22897b-16b43c30 is ringing
[Oct 14 11:25:03] VERBOSE[6713] logger.c: – SIP/22897-16b92410 is ringing
[Oct 14 11:25:03] VERBOSE[6713] logger.c: – SIP/22897-16b92410 answered Zap/1-1
[Oct 14 11:25:15] VERBOSE[6713] logger.c: – Started music on hold, class ‘default’, on Zap/1-1
[Oct 14 11:25:15] VERBOSE[6713] logger.c: == Spawn extension (PSTN1, s, 5) exited non-zero on ‘Zap/1-1’
[Oct 14 11:25:15] VERBOSE[6714] logger.c: – Started music on hold, class ‘default’, on Zap/1-1
[Oct 14 11:25:15] VERBOSE[6714] logger.c: == Parked Zap/1-1 on 301@parkedfeat. Will timeout back to extension [PSTN1] s, 5 in 360 seconds
[Oct 14 11:25:15] VERBOSE[6714] logger.c: – <SIP/22897-16b92410> Playing ‘digits/3’ (language ‘en’)
[Oct 14 11:25:16] VERBOSE[6714] logger.c: – <SIP/22897-16b92410> Playing ‘digits/0’ (language ‘en’)
[Oct 14 11:25:17] VERBOSE[6714] logger.c: – <SIP/22897-16b92410> Playing ‘digits/1’ (language ‘en’)
[Oct 14 11:25:17] VERBOSE[6714] logger.c: – Added extension ‘301’ priority 1 to parkedfeat
[Oct 14 11:25:17] VERBOSE[6356] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 510
[Oct 14 11:25:17] VERBOSE[6356] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 515
[Oct 14 11:25:17] VERBOSE[6356] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 516
/
log of Call parking normally */

/* log of Call parking Slow */
OSE[1935] logger.c: – SIP/539e-1289fad0 is ringing
[Oct 13 14:52:07] VERBOSE[1935] logger.c: – SIP/528e-129160b0 is ringing
[Oct 13 14:52:07] VERBOSE[1935] logger.c: – SIP/526e-12911a00 is ringing
[Oct 13 14:52:07] VERBOSE[1935] logger.c: – SIP/531e-12958680 is ringing
[Oct 13 14:52:08] VERBOSE[1935] logger.c: – SIP/516-128ca800 answered Zap/4-1
[Oct 13 14:52:15] VERBOSE[3044] logger.c: Extension Changed 515[icmextensions] new state Idle for Notify User 510
[Oct 13 14:52:15] VERBOSE[3044] logger.c: Extension Changed 515[icmextensions] new state Idle for Notify User 516
[Oct 13 14:52:17] VERBOSE[1935] logger.c: – Started music on hold, class ‘default’, on Zap/4-1
[Oct 13 14:52:17] VERBOSE[1935] logger.c: == Spawn extension (PSTN4, s, 8) exited non-zero on ‘Zap/4-1’
[Oct 13 14:52:17] VERBOSE[1936] logger.c: – Started music on hold, class ‘default’, on Zap/4-1
[Oct 13 14:52:17] VERBOSE[1936] logger.c: == Parked Zap/4-1 on 301@parkedfeat. Will timeout back to extension [PSTN4] s, 8 in 360 seconds
[Oct 13 14:52:17] VERBOSE[1936] logger.c: – <SIP/516-128ca800> Playing ‘digits/3’ (language ‘en’)
[Oct 13 14:52:18] VERBOSE[1936] logger.c: – <SIP/516-128ca800> Playing ‘digits/0’ (language ‘en’)
[Oct 13 14:52:19] VERBOSE[1936] logger.c: – <SIP/516-128ca800> Playing ‘digits/1’ (language ‘en’)
[Oct 13 14:52:19] VERBOSE[1936] logger.c: – Added extension ‘301’ priority 1 to parkedfeat
[Oct 13 14:52:20] VERBOSE[3044] logger.c: Extension Changed 510[icmextensions] new state Idle for Notify User 515
[Oct 13 14:52:20] VERBOSE[3044] logger.c: Extension Changed 510[icmextensions] new state Idle for Notify User 516
[Oct 13 14:52:20] VERBOSE[3044] logger.c: Extension Changed 510[icmextensions] new state Idle for Notify User 533
[Oct 13 14:52:20] VERBOSE[3044] logger.c: Extension Changed 510[icmextensions] new state Idle for Notify User 538e
[Oct 13 14:52:20] VERBOSE[3044] logger.c: Extension Changed 510[icmextensions] new state Idle for Notify User 526
[Oct 13 14:52:22] VERBOSE[3044] logger.c: Extension Changed 516[icmextensions] new state Idle for Notify User 510
[Oct 13 14:52:22] VERBOSE[3044] logger.c: Extension Changed 516[icmextensions] new state Idle for Notify User 533
[Oct 13 14:52:22] VERBOSE[3044] logger.c: Extension Changed 516[icmextensions] new state Idle for Notify User 538e
[Oct 13 14:52:22] VERBOSE[3044] logger.c: Extension Changed 516[icmextensions] new state Idle for Notify User 526
[Oct 13 14:52:59] VERBOSE[3113] logger.c: – Registered IAX2 to ‘213.166.5.130’, who sees us as 84.203.245.122:47069 with no messages waiting

[Oct 13 14:53:18] VERBOSE[3044] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 515
[Oct 13 14:53:18] VERBOSE[3044] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 510
[Oct 13 14:53:18] VERBOSE[3044] logger.c: Extension Changed 301[parkedcalls] new state InUse for Notify User 516
/* log of Call parking Slow */

Can some one with the credential remove the 2 previous posts pleas.
I only meant to psot it once. Sorry.