Halef / Tickets / #83 ORANGE: NullPointerException in Cairo is killing Halef at multiple places

David Suendermann-Oeft - 2015-08-24

summary: Call crashing after first prompt is played back and user responds; InterrruptedException/RTPStreamReplicator --> NullPointerException at
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-24

summary: NullPointerException at --> NullPointerException at RTPStreamReplicator
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-25

The above log snippet is immediately preceded by the following:

958466 Exception in thread "Thread-31" java.lang.NullPointerException
958467 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF.waitForResult(SphinxRecEngineJSGF.java:199)
958468 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF.access$100(SphinxRecEngineJSGF.java:52)
958469 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF$RecogThread.run(SphinxRecEngineJSGF.java:249)

That is, this is a duplicate of https://sourceforge.net/p/halef/tickets/82. I will close the other case in keep this one open.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-25

summary: NullPointerException at RTPStreamReplicator --> NullPointerException at SphinxRecEngineJSGF/RTPStreamReplicator
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-25

We are now able to track this issue in the DB:

select * from haleflogs where message like '%NullPointerException%';

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-25

This is also happening with Kaldi:

Exception in thread "Thread-185" java.lang.NullPointerException
at org.speechforge.cairo.server.recog.sphinx.KaldiRecEngineWFST.vad(KaldiRecEngineWFST.java:411)
at org.speechforge.cairo.server.recog.sphinx.KaldiRecEngineWFST.access$200(KaldiRecEngineWFST.java:84)
at org.speechforge.cairo.server.recog.sphinx.KaldiRecEngineWFST$VADThread.run(KaldiRecEngineWFST.java:422)

on TJR199

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

And another one on TJR212:

 [java] Exception in thread "Thread-20" java.lang.NullPointerException
 [java]     at org.jvoicexml.implementation.mrcpv2.Mrcpv2SpokenInput.recognitionEventReceived(Mrcpv2SpokenInput.java:548)
 [java]     at org.speechforge.cairo.client.SpeechClientImpl.fireRecogEvent(SpeechClientImpl.java:1286)
 [java]     at org.speechforge.cairo.client.SpeechClientImpl.recogEventReceived(SpeechClientImpl.java:389)
 [java]     at org.speechforge.cairo.client.SpeechClientImpl.eventReceived(SpeechClientImpl.java:180)
 [java]     at org.mrcp4j.client.MrcpChannel.handleMessage(MrcpChannel.java:180)
 [java]     at org.mrcp4j.client.MrcpSocket$ReadThread.run(MrcpSocket.java:110)

David Suendermann-Oeft - 2015-08-25

summary: NullPointerException at SphinxRecEngineJSGF/RTPStreamReplicator --> NullPointerException in Cairo is killing Halef at multiple places
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-26

summary: NullPointerException in Cairo is killing Halef at multiple places --> ORANGE: NullPointerException in Cairo is killing Halef at multiple places
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-26

One can now view NPE stats in the DB by running:

drop table tmpId;
create table tmpId (select callId from hli where message like '%NullPointerException%');
select * from cr where cairoCallId in (select callId from tmpId);

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-08-28

Yesterday, we had 7 NULL calls in production:

create table tmpI (select cairoCallId from cr where date = 20150827 and halefcheck = 'PASSED' and c = 0 and extension = 2222);

Five of them had NPEs:

select * from hli where callId in (select * from tmpI) and message like '%nullp%';

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-09-30

69285d5dc994661579c70c117a1382b9@141.31.8.62: no caller input

273c17682e0b45d766b05765d556e585@141.31.8.62: Halef stops listening after "sorry I did not catch that does lunch on Tuesday work for you"

9648c5ac8e92918e39edda2ced7dfec2@141.31.8.62: Halef stops listening after "it would be nice if we could..."

943fd2b9b5b5180683878a20c0dd9113@141.31.8.62: Halef stops listening after "it would be nice if we could..."

8fb7e93bc6b7474376722b8dac862693@141.31.8.62: input is just noise

I now placed a successful call into 7704. So, Halef is still up. @Patrick, there are 14 NPEs today:

select * from calls where callId in (select * from tmpId) and timestamp > '20150929';

Are they the cause of the issue?

Yours,

DSO

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-02

select count(1) from completeCalls2 where timestamp > '20150927';

214 calls this week so far

select count(1) from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444);

169 in production

select count(1) from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and code is null;

131 of null production calls (!)

select count(1) from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and code is null and halefcheck = 'PASSED';

60 of null production calls (!) passing to Halef

select * from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and code is null and halefcheck = 'PASSED' and cairoCallId is not null;

49 of these calls made it into Halef

create table tmpnpe as select callId from npe where databasedate > '20150927';

38 NPEs this week

select * from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and halefcheck = 'PASSED' and cairoCallId is not null and cairoCallId in (select * from tmpnpe);

34 of those into production Exts

select code from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and halefcheck = 'PASSED' and cairoCallId is not null and cairoCallId in (select * from tmpnpe) and code is null;

24 of them producing incomplete calls.

These are, however, complete calls featuring NPEs:

| 6198dcf84cef5a147a0d724095981bce@141.31.8.62 |
| e08405830d8001612ad879133b09bf0e@141.31.8.62 |
| 08d1dfbc48331b1a66be8034a90c6dd0@141.31.8.62 |
| ebf44e881db7410ff5fdf43384826d89@141.31.8.62 |
| 747a82e2a6d33e4c98216db6785ac465@141.31.8.62 |
| 26fb430a98e8267434a7232e4736faf0@141.31.8.62 |
| d9bebbbdee3a08a22b9d12bfd2406e25@141.31.8.62 |
| afc3212933c95076db26b58f6ff97fcb@141.31.8.62 |
| 83e6744f7e466e9c6c9e32cdbbc0f9fe@141.31.8.62 |
| 0f7573c3703d6c7cdba0179a33da1ef5@141.31.8.62 |

select cairocallid from completeCalls2 where timestamp > '20150927' and extension in (1111,2222,3333,4444) and halefcheck = 'PASSED' and cairoCallId is not null and cairoCallId in (select * from tmpnpe) and code is not null;

It would be interesting to understand whether NPEs always lead to Halef dying or not. What about the above examples?

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-14

Just called into 7702. After the third speech input, I got (on TJR200, Cairo logs)

1568784 2015-10-14 20:00:14,696 DEBUG ~.~.~.MrcpRequestProcessorImpl [Thread-770]: getNextEvent(): waiting to take event from queue...
1568785 2015-10-14 20:00:14,701 DEBUG ~.~.~.~.~.~.RawAudioProcessor [Thread-776]: adding DataStartSignal...
1568786 2015-10-14 20:00:14,724 DEBUG ~.~.~.~.~.~.SphinxRecEngine [Thread-777]: recognize without hotword mode enabled
1568787 2015-10-14 20:00:14,746 DEBUG ~.~.~.~.~.~.SpeechDataMonitor [Thread-777]: >>>>>>>>>>>>>>> DataEndSignal encountered!
1568788 2015-10-14 20:00:14,751 DEBUG ~.~.~.~.~.~.SpeechDataRecorder [Thread-777]: >>>>>>>>>>>>>>> DataEndSignal encountered!
1568789 2015-10-14 20:00:14,758 DEBUG ~.~.~.~.~.~.SphinxRecEngine [Thread-777]: ---------- Recognizer result is NULL -------
1568790 Exception in thread "Thread-777" java.lang.NullPointerException
1568791 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF.waitForResult(SphinxRecEngineJSGF.java:199)
1568792 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF.access$100(SphinxRecEngineJSGF.java:52)
1568793 at org.speechforge.cairo.server.recog.sphinx.SphinxRecEngineJSGF$RecogThread.run(SphinxRecEngineJSGF.java:249)

The call waited here until I hung up.

What is this? Is it possible that a NPE is thrown b/c the recognizer returned an empty string?

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-15

Another NPE of the type "Recognizer result is NULL" in call 7792f6f2aa58e7cc2c7d7b6afe4da297@141.31.8.62

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-15

And another one: cb58b7aad743ebb54c5f4387556a689e@141.31.8.62

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-15

It is weird. I just produced another three NPEs in a row:

26a02c3394937661bc8f57738b570a67@141.31.8.62
48ecd3ed6065aed351ca2e2c0fd11b89@141.31.8.62
308614133a3b5c774054ad8d33ad67b5@141.31.8.62

and, after a restart of Halef, the call went through smoothly:

37f2f1b093d90831e41860d26144e4ce@141.31.8.62

I also observed, that in those calls affected by NPEs, the recognizer was much more sensitive, effectively picking up background noise as speech, while, after restart, I had to speak clearly to trigger a speech event.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Suendermann-Oeft - 2015-10-16

This NPE currently does not seem to be logged in the DB (see the above calls as examples). However, the message ' ---------- Recognizer result is NULL -------' does get logged.

create table tmp as select callId from hli where message='---------- Recognizer result is NULL -------';

--262

select count(1) from completeCalls where callId in (select * from tmp) and code is null;

--221

84% of the calls exhibiting this issue are "not completed";

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Patrick L. Lange - 2015-10-16

This is related to sphinx code. The result object is null in these cases. I am interested if we see this in the kaldi-enabled version because this code is used as VAD.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ORANGE: NullPointerException in Cairo is killing Halef at multiple places

Open Source VXML-Based Spoken Dialog System

Milestone

Searches

Help

#83 ORANGE: NullPointerException in Cairo is killing Halef at multiple places

Discussion