search

unispeech / unimrcp

Open source cross-platform implementation of MRCP protocol
http://www.unimrcp.org
Apache License 2.0
380 stars 167 forks source link

Deadlocks #280

Closed andrenatal closed 4 years ago

andrenatal commented 4 years ago

Hello everyone!

I'm having some deadlocks when using my custom plugin that I can't figure what's the root cause.

For example, after having START-INPUT-TIMERS sent [1], like in the log below, the main thread does not process the start-of-input event like a normal situation [2], and starts to hang when receiving new requests [3].

The situation is pretty intermittent and sometimes the server can run for hours without problems, and sometimes just few minutes.

Does anyone have an idea about what can be causing the server to reach this state of unresponsiveness?

Thanks

Andre

[1]

MRCP/2.0 86 START-INPUT-TIMERS 3
Channel-Identifier: 969b4b4498324306@speechrecog

2020-10-14 19:06:31:864255 [INFO]   Process START-INPUT-TIMERS Request <969b4b4498324306@speechrecog> [3]
2020-10-14 19:06:31:864510 [INFO]   Process START-INPUT-TIMERS Response <969b4b4498324306@speechrecog> [3]
2020-10-14 19:06:31:864545 [INFO]   Send MRCPv2 Data 172.17.50.140:1544 <-> 172.17.50.140:41233 [80 bytes]
MRCP/2.0 80 3 200 COMPLETE
Channel-Identifier: 969b4b4498324306@speechrecog

[2]

20020-10-14 18:59:19:102395 [INFO]   Process START-OF-INPUT Event <2520e7ef56964cb2@speechrecog> [2]
2020-10-14 18:59:19:102456 [INFO]   Send MRCPv2 Data 172.17.50.140:1544 <-> 172.17.50.140:39934 [94 bytes]
MRCP/2.0 94 START-OF-INPUT 2 IN-PROGRESS
Channel-Identifier: 2520e7ef56964cb2@speechrecog

[3]


2020-10-14 19:08:23:712567 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:23:712590 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:23:712600 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:23:712620 [INFO]   Create Session 0x7fa3940252c8 <new> [uni2]
2020-10-14 19:08:23:712630 [INFO]   Remote SDP 0x7fa3940252c8 <new>
v=0
o=Asterisk 4810158394838613882 2114474979864492256 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4242 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:25:202557 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:25:202587 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:25:202594 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:25:202612 [INFO]   Create Session 0x7fa3940273a8 <new> [uni2]
2020-10-14 19:08:25:202619 [INFO]   Remote SDP 0x7fa3940273a8 <new>
v=0
o=Asterisk 6758485724662810351 9075431486233990325 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4244 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:31:302538 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:31:302597 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:31:302608 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:31:302630 [INFO]   Create Session 0x7fa394029ad8 <new> [uni2]
2020-10-14 19:08:31:302638 [INFO]   Remote SDP 0x7fa394029ad8 <new>
v=0
o=Asterisk 8757800091944689976 115756844548937019 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4246 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:36:462545 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:36:462576 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:36:462585 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:36:462606 [INFO]   Create Session 0x7fa39402bae8 <new> [uni2]
2020-10-14 19:08:36:462614 [INFO]   Remote SDP 0x7fa39402bae8 <new>
v=0
o=Asterisk 7666945217889800148 7940975369336265928 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4248 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:36:622494 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:36:622524 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:36:622531 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:36:622549 [INFO]   Create Session 0x7fa39402de08 <new> [uni2]
2020-10-14 19:08:36:622557 [INFO]   Remote SDP 0x7fa39402de08 <new>
v=0
o=Asterisk 2824073162706949913 3942848301032378607 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4250 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:43:012660 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:43:012688 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:43:012697 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:43:012720 [INFO]   Create Session 0x7fa394030128 <new> [uni2]
2020-10-14 19:08:43:012729 [INFO]   Remote SDP 0x7fa394030128 <new>
v=0
o=Asterisk 8702562025228195913 2337940917675731040 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4252 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:44:392582 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:44:392616 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:44:392624 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:44:392643 [INFO]   Create Session 0x7fa3940328e8 <new> [uni2]
2020-10-14 19:08:44:392650 [INFO]   Remote SDP 0x7fa3940328e8 <new>
v=0
o=Asterisk 482086000569682599 5409160927624658538 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4254 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:47:412589 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:47:412611 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:47:412617 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:47:412635 [INFO]   Create Session 0x7fa3940348f8 <new> [uni2]
2020-10-14 19:08:47:412641 [INFO]   Remote SDP 0x7fa3940348f8 <new>
v=0
o=Asterisk 8514159354505694971 3229754109671750753 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4256 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
a=mid:1

2020-10-14 19:08:51:462567 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:51:462595 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
2020-10-14 19:08:51:462603 [NOTICE] SIP Call State  [received]
2020-10-14 19:08:51:462623 [INFO]   Create Session 0x7fa394036ff8 <new> [uni2]
2020-10-14 19:08:51:462630 [INFO]   Remote SDP 0x7fa394036ff8 <new>
v=0
o=Asterisk 2989741322715185731 2041289155135481702 IN IP4 172.17.50.140
s=-
c=IN IP4 172.17.50.140
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4258 RTP/AVP 0 8 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendonly
a=ptime:20
andrenatal commented 4 years ago

I found the solution and root cause for the deadlocks. Closing.