|
List Info
Thread: Long delays for DTMF - Seems that 200 OK is "lost"
|
|
| Long delays for DTMF - Seems that 200 OK
is "lost" |
|
2006-08-21 20:15:32 |
Paul,
I'm not sure whether I can help, but I can at least try to
give some
clarifications.
finished.Wait() blocks until the transaction is considered
to have
finished. Due to some SIP timer requirements (check RFC
3261),
finished.Wait() originally blocked for at least 5s after the
200 OK
was received. This was unacceptable in case of hangups and
unregistration, where this sync point was used as well.
I've then
applied a quick fix, that unblocks the sync point as soon as
the
transaction is considered complete.
It may be that I've done something wrong there. At least,
since
you've mentioned "finished.Wait()", I was
instantly alerted.
Make sure that the SIP Transaction is really added to the
corresponding transactions list in either the endpoint or
connection.
In doubt, have a look at sippdu, revision 2.93 of CVS HEAD.
Unfortunately, I do not have time to work on some issues in
OPAL
library - at least not for the next couple of weeks. I am
not happy
with the patch I've commited in 2.93 and have planned to
review the
code and to implement a better solution.
Hannes
On 21. Aug 2006, at 21:02, Paul Rolland wrote:
> Hello,
>
> Any idea on this one ? I'm really stucked on it, and I
really can't
> find
> what's going on :(((((
>
> Regards,
> Paul
>
> Paul Rolland, rol(at)as2917.net
> ex-AS2917 Network administrator and Peering Coordinator
>
> --
>
> Please no HTML, I'm not a browser - Pas d'HTML, je ne
suis pas un
> navigateur
> "Some people dream of success... while others
wake up and work hard
> at it"
>
> "I worry about my child and the Internet all the
time, even though
> she's too
> young to have logged on yet. Here's what I worry
about. I worry
> that 10 or 15
> years from now, she will come to me and say 'Daddy,
where were you
> when they
> took freedom of the press away from the
Internet?'"
> --Mike Godwin, Electronic Frontier Foundation
>
>
>> -----Original Message-----
>> From: openh323-admin openh323.org
>> [mailto:openh323-adminopenh323.org] On Behalf Of
Paul Rolland
>> Sent: Friday, August 18, 2006 4:11 PM
>> To: openh323openh323.org
>> Cc: rolas2917.net
>> Subject: RE: [OpenH323]Long delays for DTMF - Seems
that 200
>> OK is "lost"
>>
>> Hello,
>>
>> Digging into the code shows that we are blocked at
>> GetSIPConnectionWithLock
>> in the following piece of code :
>>
>> BOOL SIPEndPoint::OnReceivedPDU(OpalTransport &
transport,
>> SIP_PDU * pdu)
>> {
>> // Adjust the Via list
>> if (pdu && pdu->GetMethod() !=
SIP_PDU::NumMethods)
>> pdu->AdjustVia(transport);
>>
>> // Find a corresponding connection
>> PTRACE(1, "EndPoint\tFind a corresponding
connection");
>> PSafePtr<SIPConnection> connection =
>> GetSIPConnectionWithLock(pdu->GetMIME().G
>> etCallID());
>> PTRACE(1, "EndPoint\tGot a corresponding
connection");
>> ...
>>
>> How is it possible to analyse/debug this more
precisely ?
>>
>> PS : This is done using the "simple"
application from the
>> samples directory...
>>
>> Paul
>>
>> Paul Rolland, rol(at)as2917.net
>> ex-AS2917 Network administrator and Peering
Coordinator
>>
>> --
>>
>> Please no HTML, I'm not a browser - Pas d'HTML,
je ne suis
>> pas un navigateur
>> "Some people dream of success... while others
wake up and
>> work hard at it"
>>
>> "I worry about my child and the Internet all
the time, even
>> though she's too
>> young to have logged on yet. Here's what I worry
about. I
>> worry that 10 or 15
>> years from now, she will come to me and say
'Daddy, where
>> were you when they
>> took freedom of the press away from the
Internet?'"
>> --Mike Godwin, Electronic Frontier Foundation
>>
>>
>>> -----Original Message-----
>>> From: openh323-adminopenh323.org
>>> [mailto:openh323-adminopenh323.org] On Behalf Of
Paul Rolland
>>> Sent: Friday, August 18, 2006 3:05 PM
>>> To: openh323openh323.org
>>> Cc: rolas2917.net
>>> Subject: [OpenH323]Long delays for DTMF - Seems
that 200 OK
>> is "lost"
>>>
>>> Hello,
>>>
>>> I'm trying to figure out why sending a DTMF
(SIP mode,
>>> info-tone) is so
>>> long...
>>> To help, I've added some traces in the
sippdu.cxx file, and
>>> here they are :
>>>
>>> Sending "1" to
>>> 1a1b269c-212d-db11-8988-0030484233faref-dev.def.com.com
>>> 0:21.235 SimpleOPAL
sipcon.cxx(2678) SIP
>>> SendUserInputTime('1', 0), using mode
SendUserInputAsTone
>>> 0:21.238 SimpleOPAL
sipcon.cxx(2696) SIP
>>> Calling Wait()
>>> 0:21.240 SimpleOPAL
sippdu.cxx(2052) Transaction
>>> Sending PDU via connection
>>> 0:21.241 SimpleOPAL
sippdu.cxx(2054)
>>> Transaction Sent
>>> PDU via connection
>>> 0:21.241 SimpleOPAL
sippdu.cxx(2073)
>>> Transaction Start
>>> done, Wait()ing for finished
>>> 0:37.242 Housekeeper
sippdu.cxx(2303) SIP
>> Signal
>>> transaction as finished
>>> 0:37.242 SimpleOPAL
sippdu.cxx(2075) Transaction
>>> finished is ...
>>> 0:37.243 SimpleOPAL
sipcon.cxx(2698) SIP
>>> Returning from
>>> Wait()
>>> 0:37.243 SimpleOPAL
sippdu.cxx(2022) SIP
>>> Transaction 1
>>> INFO destroyed.
>>> 0:37.244 SimpleOPAL
sipcon.cxx(2709) SIP
>>> Calling
>>> OpalConnection::SendUserInputTone
>>> 0:37.244 SimpleOPAL
connection.cxx(1036) Connection
>>> Calling rfc2833 handler
>>> 0:37.245 SimpleOPAL
connection.cxx(1038) Connection
>>> Returning rfc2833 handler
>>> Sent
>>>
>>> The problem seems to be in sippdu.cxx, when
running :
>> finished.Wait()
>>> as the PSyncPoint seems to be released by
"Housekeeper".
>>>
>>> But, at the same time, running a tcpdump show
that the INFO
>>> message is
>>> followed instantly by a 200 OK :
>>>
>>> 13:01:15.908425 ref-dev.def.com.com..34060 >
>>> ref-dev.def.com.com..34055: udp
>>> 582 (DF)
>>> 0x0000 4500 0262 0000 4000 4011 b712 c0a8
0014
>>> E..b..........
>>> 0x0010 c0a8 0014 850c 8507 024e 2db5 494e
464f
>>> .........N-.INFO
>>> 0x0020 2073 6970 3a73 7570 2e61 6463 6f6d
3140
>>> .sip:sup.adcom1
>>> 0x0030 3139 322e 3136 382e 302e 3230 3a33
3430
>>> 192.168.0.20:340
>>> 0x0040 3535 3b74 7261 6e73 706f 7274 3d75
6470
>>> 55;transport=udp
>>> 0x0050 2053 4950 2f32 2e30 0d0a 4353 6571
3a20
>>> .SIP/2.0..CSeq:.
>>> 0x0060 3120 494e 464f 0d0a 5669 613a 2053
4950
>>> 1.INFO..Via:.SIP
>>> 0x0070 2f32 2e30 2f55 4450 2031 3932 2e31
3638
>>> /2.0/UDP.192.168
>>> .....
>>> 0x01f0 4745 2c49 4e46 4f2c 5049 4e47 0d0a
436f
>>> GE,INFO,PING..Co
>>> 0x0200 6e74 656e 742d 5479 7065 3a20 6170
706c
>>> ntent-Type:.appl
>>> 0x0210 6963 6174 696f 6e2f 6474 6d66 2d72
656c
>>> ication/dtmf-rel
>>> 0x0220 6179 0d0a 436f 6e74 656e 742d 4c65
6e67
>>> ay..Content-Leng
>>> 0x0230 7468 3a20 3232 0d0a 4d61 782d 466f
7277
>>> th:.22..Max-Forw
>>> 0x0240 6172 6473 3a20 3230 0d0a 0d0a 5369
676e
>>> ards:.20....Sign
>>> 0x0250 616c 3d32 0d0a 4475 7261 7469 6f6e
3d30
>>> al=2..Duration=0
>>> 0x0260 0d0a
..
>>> 13:01:15.916301 ref-dev.def.com.com..34055 >
>>> ref-dev.def.com.com..34060: udp
>>> 403 (DF)
>>> 0x0000 4500 01af 0000 4000 4011 b7c5 c0a8
0014
>>> E.............
>>> 0x0010 c0a8 0014 8507 850c 019b 9748 5349
502f
>>> ...........HSIP/
>>> 0x0020 322e 3020 3230 3020 4f4b 0d0a 4353
6571
>>> 2.0.200.OK..CSeq
>>> 0x0030 3a20 3120 494e 464f 0d0a 5669 613a
2053
>>> :.1.INFO..Via:.S
>>> 0x0040 4950 2f32 2e30 2f55 4450 2031 3932
2e31
>>> IP/2.0/UDP.192.1
>>> 0x0050 3638 2e30 2e32 303a 3334 3036 300d
0a46
>>> 68.0.20:34060..F
>>> 0x0060 726f 6d3a 203c 7369 703a 7573 6572
4031
>>> rom:.<sip:user1
>>> ...
>>> 0x0170 5945 2c43 414e 4345 4c2c 4e4f 5449
4659
>>> YE,CANCEL,NOTIFY
>>> 0x0180 2c52 4546 4552 2c4d 4553 5341 4745
2c49
>>> ,REFER,MESSAGE,I
>>> 0x0190 4e46 4f2c 5049 4e47 0d0a 436f 6e74
656e
>>> NFO,PING..Conten
>>> 0x01a0 742d 4c65 6e67 7468 3a20 300d 0a0d 0a
>>> t-Length:.0....
>>>
>>> It does look as if the "200 OK"
message is not handled...
>>>
>>> Any idea ?
>>>
>>> Regards,
>>> Paul
>>>
>>>
------------------------------------------------------------
--
>>> ----------
>>> Check the FAQ before asking! -
>>> http://www.
openh323.org/~openh323/fom.cgi
>>> The OpenH323 Project mailing list, using
Mailman. To unsubscribe or
>>> change your subscription options, goto
>>> htt
p://www.openh323.org/mailman/listinfo/openh323
>>> Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
>>>
------------------------------------------------------------
--
>>> ----------
>>>
>>
>>
------------------------------------------------------------
--
>> ----------
>> Check the FAQ before asking! -
>> http://www.
openh323.org/~openh323/fom.cgi
>> The OpenH323 Project mailing list, using Mailman.
To unsubscribe or
>> change your subscription options, goto
>> htt
p://www.openh323.org/mailman/listinfo/openh323
>> Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
>>
------------------------------------------------------------
--
>> ----------
>>
>
>
------------------------------------------------------------
----------
> --
> Check the FAQ before asking! - http://www.openh32
3.org/~openh323/
> fom.cgi
> The OpenH323 Project mailing list, using Mailman. To
unsubscribe or
> change your subscription options, goto
> htt
p://www.openh323.org/mailman/listinfo/openh323
> Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
>
------------------------------------------------------------
----------
> --
------------------------------------------------------------
------------
Check the FAQ before asking! - http://www.
openh323.org/~openh323/fom.cgi
The OpenH323 Project mailing list, using Mailman. To
unsubscribe or
change your subscription options, goto
htt
p://www.openh323.org/mailman/listinfo/openh323
Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
------------------------------------------------------------
------------
|
|
| Long delays for DTMF - Seems that 200 OK
is "lost" |
|
2006-08-22 06:04:11 |
Hello Hannes;
> I'm not sure whether I can help, but I can at least
try to give some
> clarifications.
Thanks for your time and details !!!
> finished.Wait() blocks until the transaction is
considered to have
> finished. Due to some SIP timer requirements (check RFC
3261),
> finished.Wait() originally blocked for at least 5s
after the 200 OK
> was received. This was unacceptable in case of hangups
and
> unregistration, where this sync point was used as well.
I've then
> applied a quick fix, that unblocks the sync point as
soon as the
> transaction is considered complete.
Well, it's not precisely finished.Wait() that seems to the
the real
culprit, as digging more into the code seems to show that
I'm stuck in
writerSemaphore.Wait();
inside
PReadWriteMutex::StartWrite (this=0x80a35a8) at
../common/osutils.cxx:2571
when doing a GetSIPConnectionWithLock()
This occurs when I receive a 200 OK PDU as a reply to an
INFO I sent
to signal DTMF.
From reading the code, it seems that the locking mechanism
is done to be
very local to a scope, so a ReadWrite lock acquired thru
GetSIPConnectionWithLock is expected to last only as long as
the returned
pointer exists.
As this function in only called in
SIPEndPoint::OnReceivedPDU, I've
been PTRACE'ing enter and exit of this function, to make
sure that they
are balanced, and though they definitely are (or behave as
if), I still
have this lock.
> It may be that I've done something wrong there. At
least, since
> you've mentioned "finished.Wait()", I was
instantly alerted.
> Make sure that the SIP Transaction is really added to
the
> corresponding transactions list in either the endpoint
or connection.
> In doubt, have a look at sippdu, revision 2.93 of CVS
HEAD.
If it was not added, what would be the result ? I would
expect to see
GetSIPConnectionWithLock to return a NULL pointer (or
equivalent) to indicate
that no connection has been found, but this shouldn't
create a lock inside
the Get... call. Or is there something unusual I should
expect ?
> Unfortunately, I do not have time to work on some
issues in OPAL
> library - at least not for the next couple of weeks. I
am not happy
> with the patch I've commited in 2.93 and have planned
to review the
> code and to implement a better solution.
I'll try to find time to analyze more precisely, and I'll
keep you informed.
I suspect that the addition of the SIP transaction is also a
ReadWrite locked
operation, so I might have a look at this, as it is possible
that I'm still
lock at the point I add the transaction when I already
receive and process
the reply... But, the Wait() should allow the adding thread
to run, and thus
Signal() ...
Damn, really weird :(
Thanks again,
Paul
------------------------------------------------------------
------------
Check the FAQ before asking! - http://www.
openh323.org/~openh323/fom.cgi
The OpenH323 Project mailing list, using Mailman. To
unsubscribe or
change your subscription options, goto
htt
p://www.openh323.org/mailman/listinfo/openh323
Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
------------------------------------------------------------
------------
|
|
| Long delays for DTMF - Seems that 200 OK
is "lost" |
|
2006-08-22 06:04:11 |
Hello Hannes;
> I'm not sure whether I can help, but I can at least
try to give some
> clarifications.
Thanks for your time and details !!!
> finished.Wait() blocks until the transaction is
considered to have
> finished. Due to some SIP timer requirements (check RFC
3261),
> finished.Wait() originally blocked for at least 5s
after the 200 OK
> was received. This was unacceptable in case of hangups
and
> unregistration, where this sync point was used as well.
I've then
> applied a quick fix, that unblocks the sync point as
soon as the
> transaction is considered complete.
Well, it's not precisely finished.Wait() that seems to the
the real
culprit, as digging more into the code seems to show that
I'm stuck in
writerSemaphore.Wait();
inside
PReadWriteMutex::StartWrite (this=0x80a35a8) at
../common/osutils.cxx:2571
when doing a GetSIPConnectionWithLock()
This occurs when I receive a 200 OK PDU as a reply to an
INFO I sent
to signal DTMF.
From reading the code, it seems that the locking mechanism
is done to be
very local to a scope, so a ReadWrite lock acquired thru
GetSIPConnectionWithLock is expected to last only as long as
the returned
pointer exists.
As this function in only called in
SIPEndPoint::OnReceivedPDU, I've
been PTRACE'ing enter and exit of this function, to make
sure that they
are balanced, and though they definitely are (or behave as
if), I still
have this lock.
> It may be that I've done something wrong there. At
least, since
> you've mentioned "finished.Wait()", I was
instantly alerted.
> Make sure that the SIP Transaction is really added to
the
> corresponding transactions list in either the endpoint
or connection.
> In doubt, have a look at sippdu, revision 2.93 of CVS
HEAD.
If it was not added, what would be the result ? I would
expect to see
GetSIPConnectionWithLock to return a NULL pointer (or
equivalent) to indicate
that no connection has been found, but this shouldn't
create a lock inside
the Get... call. Or is there something unusual I should
expect ?
> Unfortunately, I do not have time to work on some
issues in OPAL
> library - at least not for the next couple of weeks. I
am not happy
> with the patch I've commited in 2.93 and have planned
to review the
> code and to implement a better solution.
I'll try to find time to analyze more precisely, and I'll
keep you informed.
I suspect that the addition of the SIP transaction is also a
ReadWrite locked
operation, so I might have a look at this, as it is possible
that I'm still
lock at the point I add the transaction when I already
receive and process
the reply... But, the Wait() should allow the adding thread
to run, and thus
Signal() ...
Damn, really weird :(
Thanks again,
Paul
------------------------------------------------------------
------------
Check the FAQ before asking! - http://www.
openh323.org/~openh323/fom.cgi
The OpenH323 Project mailing list, using Mailman. To
unsubscribe or
change your subscription options, goto
htt
p://www.openh323.org/mailman/listinfo/openh323
Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
------------------------------------------------------------
------------
|
|
| Long delays for DTMF - Seems that 200 OK
is "lost" |
|
2006-08-22 06:04:11 |
Hello Hannes;
> I'm not sure whether I can help, but I can at least
try to give some
> clarifications.
Thanks for your time and details !!!
> finished.Wait() blocks until the transaction is
considered to have
> finished. Due to some SIP timer requirements (check RFC
3261),
> finished.Wait() originally blocked for at least 5s
after the 200 OK
> was received. This was unacceptable in case of hangups
and
> unregistration, where this sync point was used as well.
I've then
> applied a quick fix, that unblocks the sync point as
soon as the
> transaction is considered complete.
Well, it's not precisely finished.Wait() that seems to the
the real
culprit, as digging more into the code seems to show that
I'm stuck in
writerSemaphore.Wait();
inside
PReadWriteMutex::StartWrite (this=0x80a35a8) at
../common/osutils.cxx:2571
when doing a GetSIPConnectionWithLock()
This occurs when I receive a 200 OK PDU as a reply to an
INFO I sent
to signal DTMF.
From reading the code, it seems that the locking mechanism
is done to be
very local to a scope, so a ReadWrite lock acquired thru
GetSIPConnectionWithLock is expected to last only as long as
the returned
pointer exists.
As this function in only called in
SIPEndPoint::OnReceivedPDU, I've
been PTRACE'ing enter and exit of this function, to make
sure that they
are balanced, and though they definitely are (or behave as
if), I still
have this lock.
> It may be that I've done something wrong there. At
least, since
> you've mentioned "finished.Wait()", I was
instantly alerted.
> Make sure that the SIP Transaction is really added to
the
> corresponding transactions list in either the endpoint
or connection.
> In doubt, have a look at sippdu, revision 2.93 of CVS
HEAD.
If it was not added, what would be the result ? I would
expect to see
GetSIPConnectionWithLock to return a NULL pointer (or
equivalent) to indicate
that no connection has been found, but this shouldn't
create a lock inside
the Get... call. Or is there something unusual I should
expect ?
> Unfortunately, I do not have time to work on some
issues in OPAL
> library - at least not for the next couple of weeks. I
am not happy
> with the patch I've commited in 2.93 and have planned
to review the
> code and to implement a better solution.
I'll try to find time to analyze more precisely, and I'll
keep you informed.
I suspect that the addition of the SIP transaction is also a
ReadWrite locked
operation, so I might have a look at this, as it is possible
that I'm still
lock at the point I add the transaction when I already
receive and process
the reply... But, the Wait() should allow the adding thread
to run, and thus
Signal() ...
Damn, really weird :(
Thanks again,
Paul
------------------------------------------------------------
------------
Check the FAQ before asking! - http://www.
openh323.org/~openh323/fom.cgi
The OpenH323 Project mailing list, using Mailman. To
unsubscribe or
change your subscription options, goto
htt
p://www.openh323.org/mailman/listinfo/openh323
Maintained by Quicknet Technologies, Inc - http://www.quicknet.net
------------------------------------------------------------
------------
|
|
[1-4]
|
|