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@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@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@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
>
>