0000339: JS: (dtmf) handler does not work when routing script hangs in loop

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ Issue History ] [ Print ]

Category

Severity

Reproducibility

Date Submitted

Last Update

0000339

[Yate - Yet Another Telephony Engine] module

minor

always

2013-04-18 14:43

2013-04-19 13:44

Reporter

asymetrixs

View Status

public

Assigned To

paulc

Priority

normal

Resolution

open

Status

assigned

Product Version

4.x

Summary

0000339: JS: (dtmf) handler does not work when routing script hangs in loop

Description

Right after a message like this

<yrtp:INFO> YRTPWrapper::gotDTMF('6') [0x7ff4ec01aab0]

the DTMF handler should write something like that

VALUE: 6 on chan XYZ

but that does not work when JS hangs in the loop, but it does when there is no loop.

Additional Information

SCRIPT:

function onDTMF(message)
{
        Engine.debug("VALUE: " + message.text + " on chan " + message.id);
}

Message.install(onDTMF, "chan.dtmf", 40);

if(message.direction == 'incoming')
{
        Channel.callTo("dbwave/play//tmp/voice.wav");

        Engine.debug("IN JAVASCRIPT ROUTING SCRIPT");

        while (true)
        {
                var db = new Message("database");
                db.account = "dbmain";
                db.query = "SELECT pg_sleep(3);";

                db.dispatch();

                Engine.debug("Waiting");
        }

        Engine.debug("end");
}

================================================================

OUTPUT:

Yate engine is initialized and starting up on ubuntu
<INFO> Creating new message dispatching thread (0 running)
<sip:INFO> 'udp:0.0.0.0:5060' received 922 bytes SIP message from 172.16.1.29:56802 [0xb602a0]
------
INVITE sip:492XXXXXXXXX@172.16.1.23;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-854e8c44d22eb6a0-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:4915XXXXXXXXXX@172.16.1.29:56802;transport=UDP>
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, X-cisco-serviceuri
User-Agent: Zoiper r16950
Allow-Events: presence, kpml
Content-Length: 238

v=0
o=Z 0 0 IN IP4 172.16.1.29
s=Z
c=IN IP4 172.16.1.29
t=0 0
m=audio 41468 RTP/AVP 3 110 98 8 0 101
a=rtpmap:110 speex/8000
a=rtpmap:98 iLBC/8000
a=fmtp:98 mode=20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
------
<sip:INFO> 'udp:0.0.0.0:5060' sending code 100 0x7ff4e0000960 to 172.16.1.29:56802 [0xb602a0]
------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-854e8c44d22eb6a0-1---d8754z-;rport=56802;received=172.16.1.29
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 1 INVITE
Server: YATE/4.3.1
Content-Length: 0

------
<sip/1:ALL> YateSIPConnection::YateSIPConnection(0x7ff4e00011e0,0x7ff4d801fca0) [0x7ff4e0001a00]
<sip/1:ALL> NAT address is '(null)' [0x7ff4e0001a00]
<INFO> Could not classify call from '4915XXXXXXXXXX', wasted 7 usec
<sip/1:ALL> NAT address is '(null)' [0x7ff4e0001a00]
<wave:INFO> Play from wave file '/tmp/voice.wav'
<wave/1:ALL> WaveChan::WaveChan(play) [0x7ff4ec017b60]
<wave:ALL> WaveSource::WaveSource("/tmp/voice.wav",0x7ff4ec017b60) [0x7ff4ec017dd0]
<MILD> .wav not supported yet, assuming raw signed linear
<sip/1:NOTE> Answering now call sip/1 because we have no targetid [0x7ff4e0001a00]
<yrtp:ALL> RTP/AVP message received
<yrtp:INFO> Guessed local IP '172.16.1.23' for remote '172.16.1.29'
<yrtp:ALL> YRTPWrapper::YRTPWrapper('172.16.1.23',0x7ff4e0001a00,'audio',bidir,0x7ff4ec01a140,false) [0x7ff4ec01aab0]
<yrtp:ALL> YRTPWrapper::setupRTP("172.16.1.23",true) [0x7ff4ec01aab0]
<yrtp:INFO> Session 'yrtp/934572097' 0x7ff4ec01ac20 bound to 172.16.1.23:30020 +RTCP [0x7ff4ec01aab0]
<javascript:NOTE> Channel 'sip/1' already assisted!
<yrtp:ALL> YRTPSource::YRTPSource(0x7ff4ec01aab0) [0x7ff4ec01af90]
<yrtp:ALL> YRTPConsumer::YRTPConsumer(0x7ff4ec01aab0) [0x7ff4ec01b0e0]
<INFO> DataTranslator::attachChain [0x7ff4ec017dd0] 'slin' -> [0x7ff4ec01b0e0] '(null)' not possible
<yrtp:ALL> YRTPWrapper::setupSRTP(false) [0x7ff4ec01aab0]
<sip:INFO> 'udp:0.0.0.0:5060' sending code 200 0x7ff4ec019660 to 172.16.1.29:56802 [0xb602a0]
------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-854e8c44d22eb6a0-1---d8754z-;rport=56802;received=172.16.1.29
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>;tag=1205248606
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 1 INVITE
Server: YATE/4.3.1
Contact: <sip:492XXXXXXXXX@172.16.1.23:5060>
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
Content-Type: application/sdp
Content-Length: 314

v=0
o=yate 1366285151 1366285151 IN IP4 172.16.1.23
s=SIP Call
c=IN IP4 172.16.1.23
t=0 0
m=audio 30020 RTP/AVP 3 110 98 8 0 101
a=rtpmap:3 GSM/8000
a=rtpmap:110 SPEEX/8000
a=rtpmap:98 iLBC/8000
a=fmtp:98 mode=20
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
------
<sip:INFO> 'udp:0.0.0.0:5060' received 469 bytes SIP message from 172.16.1.29:56802 [0xb602a0]
------
ACK sip:492XXXXXXXXX@172.16.1.23:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-0c52c31f4b4c9fe2-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:4915XXXXXXXXXX@172.16.1.29:56802;transport=UDP>
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>;tag=1205248606
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 1 ACK
User-Agent: Zoiper r16950
Content-Length: 0

------
<yrtp:ALL> RTP/AVP message received
<yrtp:ALL> Wrapper 0x7ff4ec01aab0 found by CallEndpoint 0x7ff4e0001a00
<yrtp:ALL> YRTPWrapper::startRTP("172.16.1.29",41468) [0x7ff4ec01aab0]
<yrtp:INFO> RTP starting format 'gsm' payload 3 [0x7ff4ec01aab0]
>>> DataTranslator::detachChain(0x7ff4ec017dd0,0x7ff4ec01b0e0)
<<< DataTranslator::detachChain
<ALL> GsmCodec::GsmCodec("slin","gsm",encoding) [0x7ff4e0007980]
<ALL> Created DataTranslator 0x7ff4e0007980 for 'slin' -> 'gsm' by factory 0x7ff50a1430a8 (len=1)
<ALL> DataTranslator::attachChain [0x7ff4ec017dd0] 'slin' -> [0x7ff4ec01b0e0] 'gsm' succeeded
<NOTE> Choosing started 'audio' format 'gsm' [0x7ff4e0008220]
<wave:ALL> WaveSource '(null)' end of data (62604 played) chan=0x7ff4ec017b60 [0x7ff4ec017dd0]
<wave:ALL> WaveSource cleanup, total=62604, chan=(nil) [0x7ff4ec017dd0]
>>> DataTranslator::detachChain(0x7ff4ec017dd0,0x7ff4ec01b0e0)
  >>> DataTranslator::detachChain(0x7ff4ec017dd0,0x7ff4e0007980)
  <<< DataTranslator::detachChain
  <ALL> GsmCodec::~GsmCodec() [0x7ff4e0007980]
<<< DataTranslator::detachChain
<sip/1:ALL> YateSIPConnection::disconnected() '(null)' [0x7ff4e0001a00]
<wave:ALL> WaveSource::~WaveSource() [0x7ff4ec017dd0] total=62604 stamp=31200
<wave:INFO> WaveSource rate=16037 b/s
<wave/1:ALL> WaveChan::~WaveChan() wave/1 [0x7ff4ec017b60]
<NOTE> IN JAVASCRIPT ROUTING SCRIPT
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'
<MILD> Creating new message dispatching thread (1 running)
<pgsqldb:ALL> Query for 'dbmain.1' returned 1 rows, 1 affected [0xa33f70]
<NOTE> Waiting
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'
<yrtp:INFO> YRTPWrapper::gotDTMF('5') [0x7ff4ec01aab0]
<pgsqldb:ALL> Query for 'dbmain.1' returned 1 rows, 1 affected [0xa33f70]
<NOTE> Waiting
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'
<MILD> Creating new message dispatching thread (2 running)
<yrtp:INFO> YRTPWrapper::gotDTMF('6') [0x7ff4ec01aab0]
<yrtp:INFO> YRTPWrapper::gotDTMF('6') [0x7ff4ec01aab0]
<yrtp:INFO> YRTPWrapper::gotDTMF('6') [0x7ff4ec01aab0]
<pgsqldb:ALL> Query for 'dbmain.1' returned 1 rows, 1 affected [0xa33f70]
<NOTE> Waiting
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'
<MILD> Creating new message dispatching thread (3 running)
<MILD> Creating new message dispatching thread (4 running)
<pgsqldb:ALL> Query for 'dbmain.1' returned 1 rows, 1 affected [0xa33f70]
<NOTE> Waiting
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'
<sip:INFO> 'udp:0.0.0.0:5060' received 469 bytes SIP message from 172.16.1.29:56802 [0xb602a0]
------
BYE sip:492XXXXXXXXX@172.16.1.23:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-e598e882cf8cdce3-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:4915XXXXXXXXXX@172.16.1.29:56802;transport=UDP>
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>;tag=1205248606
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 2 BYE
User-Agent: Zoiper r16950
Content-Length: 0

------
<sip:INFO> 'udp:0.0.0.0:5060' sending code 100 0x7ff4e0006360 to 172.16.1.29:56802 [0xb602a0]
------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-e598e882cf8cdce3-1---d8754z-;rport=56802;received=172.16.1.29
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>;tag=1205248606
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 2 BYE
Server: YATE/4.3.1
Content-Length: 0

------
<yrtp:ALL> RTP/AVP message received
<yrtp:ALL> Wrapper 0x7ff4ec01aab0 found by ID 'yrtp/934572097'
<yrtp:INFO> YRTPWrapper::terminate() [0x7ff4ec01aab0]
<yrtp:ALL> YRTPSource::~YRTPSource() [0x7ff4ec01af90] wrapper=0x7ff4ec01aab0 ts=127680
<yrtp:ALL> YRTPConsumer::~YRTPConsumer() [0x7ff4ec01b0e0] wrapper=0x7ff4ec01aab0 ts=31040
<yrtp:ALL> YRTPWrapper::~YRTPWrapper() bidir 'audio' [0x7ff4ec01aab0]
<ALL> Cleaning up RTP 0x7ff4ec01ac20 [0x7ff4ec01aab0]
<sip/1:ALL> YateSIPConnection::hangup() state=3 trans=(nil) error='(null)' code=0 reason='(null)' [0x7ff4e0001a00]
<sip:INFO> 'udp:0.0.0.0:5060' sending code 200 0x7ff4e0008220 to 172.16.1.29:56802 [0xb602a0]
------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.29:56802;branch=z9hG4bK-d8754z-e598e882cf8cdce3-1---d8754z-;rport=56802;received=172.16.1.29
From: <sip:4915XXXXXXXXXX@172.16.1.23;transport=UDP>;tag=30909f66
To: <sip:492XXXXXXXXX@172.16.1.23;transport=UDP>;tag=1205248606
Call-ID: YjEzZmIyNTg0OTYwMzMyMTAwZmE5MDc2NTdhZmQ3OTE.
CSeq: 2 BYE
P-RTP-Stat: PS=195,OS=6435,PR=807,OR=25703,PL=0
Server: YATE/4.3.1
Allow: ACK, INVITE, BYE, CANCEL, REGISTER, REFER, OPTIONS, INFO
Content-Length: 0

------
<MILD> Creating new message dispatching thread (5 running)
<pgsqldb:ALL> Query for 'dbmain.1' returned 1 rows, 1 affected [0xa33f70]
<NOTE> Waiting
<pgsqldb:ALL> Performing query "SELECT pg_sleep(3);" for 'dbmain'

Notes
(0000520) paulc (administrator) 2013-04-19 13:17	Because the Javascript language is not multithreaded any message or action in other thread waits until the instance is not in use. SVN Rev. 5465 (2013-04-12) adds the possibility of unlocking the script while a message is dispatched. The lock is reacquired before execution continues. However, because of bug 0000336 this is not yet usable in channes instance scripts.

Issue History
Date Modified	Username	Field	Change
2013-04-18 14:43	asymetrixs	New Issue
2013-04-19 13:17	paulc	Note Added: 0000520
2013-04-19 13:17	paulc	Status	new => acknowledged
2013-04-19 13:44	paulc	Status	acknowledged => assigned
2013-04-19 13:44	paulc	Assigned To	=> paulc

Relationships