[asterisk-users] Page hangs up after 5 seconds

Torbjörn Abrahamsson torbjorn.abrahamsson at gmail.com
Tue Oct 17 00:46:39 MST 2006


OK... A bit more research done... This problem does not occur in version 
1.2.7.1, which was the platform where we developed our dialplan.

Looking at a diff between app_page.c for the two version reveals that 
the only change that has been done is the addition of (5) to the w option:

1.2.7.1, line 182:
	snprintf(meetmeopts, sizeof(meetmeopts), "%ud|%sqxdw", confid, 
ast_test_flag(&flags, PAGE_DUPLEX) ? "" : "m");

1.2.12.1, line 182:
	snprintf(meetmeopts, sizeof(meetmeopts), "%ud|%sqxdw(5)", confid, 
ast_test_flag(&flags, PAGE_DUPLEX) ? "" : "m");

Why this change? And I can't imagine that it is the intended behaviour. 
Hasn't anyone else noticed this? Or are we doing something fundamentally 
wrong?

I still do not understand what the usage and result of the w option are, 
could someone elaborate?

// Torbjörn



Torbjörn Abrahamsson wrote:
> Hi asterisk-users,
> 
> We are using Asterisk 1.2.12.1, and are trying to use the Page 
> application. It seems to work but after approx 4-5 seconds the call is 
> hung up.
> 
> The dialplan code look like this:
> 
> exten => _*2XX,1,AGI(get-paging-devices.agi,${EXTEN:2})
> exten => _*2XX,n,GotoIf($[ "${PAGING_DEVICES}" = "invalid" ]?i,1)
> exten => _*2XX,n,SIPAddHeader(Call-Info: sip:192.168.20.1\; answer-after=0)
> exten => _*2XX,n,Page(${PAGING_DEVICES},dq)
> 
> 
> The CLI outputs the following:
> 
>     -- Executing AGI("SIP/snom1-b7d0c328", "get-paging-devices.agi|01") 
> in new stack
>     -- Launched AGI Script /var/lib/asterisk/agi-bin/get-paging-devices.agi
>     -- AGI Script get-paging-devices.agi completed, returning 0
>     -- Executing GotoIf("SIP/snom1-b7d0c328", "0?i|1") in new stack
>     -- Executing SIPAddHeader("SIP/snom1-b7d0c328", "Call-Info: 
> sip:192.168.20.1; answer-after=0") in new stack
>     -- Executing Page("SIP/snom1-b7d0c328", "SIP/snom1&SIP/snom3|dq") in 
> new stack
>     -- Created MeetMe conference 1023 for conference '2028709590d'
>     -- Launching MeetMe(2028709590d|qxdw(5)) on SIP/snom3-08984140
>     -- Hungup 'Zap/pseudo-1436409106'
>   == Spawn extension (wx3trunk2, *201, 4) exited non-zero on 
> 'SIP/snom1-b7d0c328'
>     -- Executing Hangup("SIP/snom1-b7d0c328", "") in new stack
> 
> 
> The 'full' log has this contents:
> 
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Launching 'Goto'
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Executing 
> Goto("SIP/snom1-b7d0c328", "wx3trunk2|*201|1") in new stack
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Goto (wx3trunk2,*201,1)
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Launching 'AGI'
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Executing 
> AGI("SIP/snom1-b7d0c328", "get-paging-devices.agi|01") in new stack
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Launched AGI Script 
> /var/lib/asterisk/agi-bin/get-paging-devices.agi
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- AGI Script 
> get-paging-devices.agi completed, returning 0
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Expression result is '0'
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Launching 'GotoIf'
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Executing 
> GotoIf("SIP/snom1-b7d0c328", "0?i|1") in new stack
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Not taking any branch
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Launching 'SIPAddHeader'
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Executing 
> SIPAddHeader("SIP/snom1-b7d0c328", "Call-Info: sip:192.168.20.1; 
> answer-after=0") in new stack
> Oct 16 11:01:12 DEBUG[6767] pbx.c: Launching 'Page'
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Executing 
> Page("SIP/snom1-b7d0c328", "SIP/snom1&SIP/snom3|dq") in new stack
> Oct 16 11:01:12 DEBUG[6767] chan_sip.c: sip_answer(SIP/snom1-b7d0c328)
> Oct 16 11:01:12 DEBUG[6767] app_meetme.c: Building dynamic conference 
> '2028709590d'
> Oct 16 11:01:12 DEBUG[6767] chan_zap.c: Using channel -2
> Oct 16 11:01:12 VERBOSE[6767] logger.c:     -- Created MeetMe conference 
> 1023 for conference '2028709590d'
> Oct 16 11:01:12 DEBUG[6767] channel.c: Set channel SIP/snom1-b7d0c328 to 
> write format slin
> Oct 16 11:01:12 DEBUG[6767] channel.c: Set channel SIP/snom1-b7d0c328 to 
> read format slin
> Oct 16 11:01:12 DEBUG[6767] app_meetme.c: Placed channel 
> SIP/snom1-b7d0c328 in ZAP conf 1023
> Oct 16 11:01:12 DEBUG[6772] app_queue.c: Device 'SIP/snom1' changed to 
> state '2' (In use) but we don't care because they're not a member of any 
> queue.
> Oct 16 11:01:12 DEBUG[6773] app_queue.c: Device 'Zap/pseudo' changed to 
> state '2' (In use) but we don't care because they're not a member of any 
> queue.
> Oct 16 11:01:12 DEBUG[6771] chan_sip.c: Allocating new SIP dialog for 
> (No Call-ID) - INVITE (With RTP)
> Oct 16 11:01:12 DEBUG[6771] res_config_mysql.c: MySQL RealTime: 
> Everything is fine.
> Oct 16 11:01:12 DEBUG[6771] res_config_mysql.c: MySQL RealTime: Retrieve 
> SQL: SELECT * FROM sipusers WHERE name = 'snom3'
> Oct 16 11:01:12 VERBOSE[6771] logger.c:     -- SIP Seeding peer from 
> astdb: 'snom3' at snom3 at 212.247.4.149:59283 for 60
> Oct 16 11:01:12 DEBUG[6771] chan_sip.c: Allocating new SIP dialog for 
> (No Call-ID) - OPTIONS (No RTP)
> Oct 16 11:01:12 DEBUG[6771] chan_sip.c: Setting NAT on RTP to 524288
> Oct 16 11:01:12 DEBUG[6771] chan_sip.c: Outgoing Call for snom3
> Oct 16 11:01:12 DEBUG[6771] chan_sip.c: Updating call counter for 
> outgoing call
> Oct 16 11:01:12 DEBUG[6767] rtp.c: Ooh, format changed from unknown to ulaw
> Oct 16 11:01:12 DEBUG[6767] rtp.c: RTCP NAT: Got RTCP from other end. 
> Now sending to address 212.247.4.149:49435
> Oct 16 11:01:12 DEBUG[6767] rtp.c: Got RTCP report of 52 bytes
> Oct 16 11:01:12 DEBUG[6767] app_meetme.c: Got unrecognized frame on 
> channel SIP/snom1-b7d0c328, f->frametype=5,f->subclass=0
> Oct 16 11:01:12 DEBUG[6767] rtp.c: RTP NAT: Got audio from other end. 
> Now sending to address 212.247.4.149:49434
> Oct 16 11:01:12 DEBUG[6767] app_meetme.c: Got unrecognized frame on 
> channel SIP/snom1-b7d0c328, f->frametype=5,f->subclass=0
> Oct 16 11:01:12 DEBUG[6771] rtp.c: RTCP NAT: Got RTCP from other end. 
> Now sending to address 212.247.4.149:58421
> Oct 16 11:01:12 DEBUG[6771] rtp.c: Got RTCP report of 52 bytes
> Oct 16 11:01:12 VERBOSE[6775] logger.c:     -- Launching 
> MeetMe(2028709590d|qxdw(5)) on SIP/snom3-08984140
> Oct 16 11:01:12 DEBUG[6775] channel.c: Set channel SIP/snom3-08984140 to 
> write format slin
> Oct 16 11:01:12 DEBUG[6775] channel.c: Set channel SIP/snom3-08984140 to 
> read format slin
> Oct 16 11:01:12 DEBUG[6775] app_meetme.c: Placed channel 
> SIP/snom3-08984140 in ZAP conf 1023
> Oct 16 11:01:12 DEBUG[6776] app_queue.c: Device 'SIP/snom3' changed to 
> state '2' (In use) but we don't care because they're not a member of any 
> queue.
> Oct 16 11:01:12 DEBUG[6775] rtp.c: RTP NAT: Got audio from other end. 
> Now sending to address 212.247.4.149:58420
> Oct 16 11:01:12 DEBUG[6775] rtp.c: Ooh, format changed from unknown to ulaw
> Oct 16 11:01:17 DEBUG[6775] channel.c: Hanging up channel 
> 'SIP/snom3-08984140'
> Oct 16 11:01:17 DEBUG[6775] chan_sip.c: Hangup call SIP/snom3-08984140, 
> SIP callid 281fa14d186c76c5545b59d8253762ca at wx3.se)
> Oct 16 11:01:17 DEBUG[6775] chan_sip.c: update_call_counter(snom3) - 
> decrement call limit counter
> Oct 16 11:01:17 DEBUG[6775] chan_sip.c: Updating call counter for 
> outgoing call
> Oct 16 11:01:17 DEBUG[6767] rtp.c: Got RTCP report of 52 bytes
> Oct 16 11:01:17 DEBUG[6767] app_meetme.c: Got unrecognized frame on 
> channel SIP/snom1-b7d0c328, f->frametype=5,f->subclass=0
> .Oct 16 11:01:18 DEBUG[6767] channel.c: Hanging up channel 
> 'Zap/pseudo-1436409106'
> Oct 16 11:01:18 DEBUG[6767] chan_zap.c: zt_hangup(Zap/pseudo-1436409106)
> Oct 16 11:01:18 DEBUG[6767] chan_zap.c: Hangup: channel: -2 index = 0, 
> normal = 20, callwait = -1, thirdcall = -1
> Oct 16 11:01:18 DEBUG[6767] chan_zap.c: Set option TDD MODE, value: 
> OFF(0) on Zap/pseudo-1436409106
> Oct 16 11:01:18 DEBUG[6767] chan_zap.c: Updated conferencing on -2, with 
> 0 conference users
> Oct 16 11:01:18 VERBOSE[6767] logger.c:     -- Hungup 
> 'Zap/pseudo-1436409106'
> Oct 16 11:01:18 DEBUG[6767] pbx.c: Spawn extension (wx3trunk2,*201,4) 
> exited non-zero on 'SIP/snom1-b7d0c328'
> Oct 16 11:01:18 DEBUG[6767] pbx.c: Launching 'Hangup'
> Oct 16 11:01:18 VERBOSE[6767] logger.c:     -- Executing 
> Hangup("SIP/snom1-b7d0c328", "") in new stack
> Oct 16 11:01:18 DEBUG[6767] pbx.c: Spawn extension (wx3trunk2,h,1) 
> exited non-zero on 'SIP/snom1-b7d0c328'
> Oct 16 11:01:18 DEBUG[6767] cdr_addon_mysql.c: cdr_mysql: inserting a 
> CDR record.
> Oct 16 11:01:18 DEBUG[6767] cdr_addon_mysql.c: cdr_mysql: SQL command as 
> follows: INSERT INTO cdr 
> (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) 
> VALUES ('2006-10-16 11:01:12','\"Phone 1\" 
> <01>','01','*201','wx3trunk2', 
> 'SIP/snom1-b7d0c328','','Hangup','',6,6,'ANSWERED',3,'','')
> Oct 16 11:01:18 DEBUG[6767] channel.c: Hanging up channel 
> 'SIP/snom1-b7d0c328'
> Oct 16 11:01:18 DEBUG[6767] chan_sip.c: Hangup call SIP/snom1-b7d0c328, 
> SIP callid 3c2697760c35-uy8jt2ru9c40 at snom320-000413240D2E)
> Oct 16 11:01:18 DEBUG[6767] chan_sip.c: update_call_counter(snom1) - 
> decrement call limit counter
> Oct 16 11:01:18 DEBUG[6767] chan_sip.c: Updating call counter for 
> incoming call
> Oct 16 11:01:18 DEBUG[6804] app_queue.c: Device 'SIP/snom1' changed to 
> state '1' (Not in use) but we don't care because they're not a member of 
> any queue.
> 
> 
> When looking at SIP-traces it seems an BYE is sent to the paged client 
> after 5 seconds, even if the calling client hangs up after a longer 
> interval.
> 
> As it is hanging up after 5 seconds it is not such a long step to start 
> thinking about 'qxdw(5)'... I'm not totally sure how to interpret what 
> the w option does. What is a marked user? And what happens when the 
> timeout occurs?
> 
> Any ideas?
> 
> BR,
> Torbjörn Abrahamsson
> 
> _______________________________________________
> --Bandwidth and Colocation provided by Easynews.com --
> 
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>   http://lists.digium.com/mailman/listinfo/asterisk-users
> 
> 


More information about the asterisk-users mailing list