[asterisk-users] Page hangs up after 5 seconds

Torbjörn Abrahamsson torbjorn.abrahamsson at gmail.com
Mon Oct 16 02:59:41 MST 2006 

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

More information about the asterisk-users mailing list