Timeout after trying to play a long file

andycitron commented 5 years ago

It seems that if the file I play is too long, tj.speak seems to timeout after speaking for a while, and then throws an exception. After that I have to restart my node.js ap to get tjbot to work again.

Is there a way to change the 'speak' timeout? Is the problem something else?

I'm doing text to speech and the text is created dynamically, so its hard to know how long it will take to speak.

jweisz commented 5 years ago

Hm, this is a good question. I've used Watson TTS to play some fairly lengthy speech, maybe 30-45 seconds long. Could you share the exception you're getting? It might help me understand what's going on. I'm also looking at the Watson TTS docs, the only limit I'm seeing is that you can only pass a maximum of 5KB of text.

https://www.ibm.com/watson/developercloud/text-to-speech/api/v1/curl.html?curl#synthesize

andycitron commented 5 years ago

Today TTS isn't cooperating. Its telling me my credentials have an issue. Seems odd, they worked yesterday. Mentioned something about "A common error is trying to use credentials from an experimental or beta release against a GA release or vice versa".

I did use a 'conversation' experimental feature, but it seems that shouldn't impact TTS credentials. Any idea why it might be unhappy about my TTS credential?

Makes getting a copy of the original exception difficult right now because it refuses to speak.

I do see that the longest string I tried to speak today was 1486 characters. Seems far from the 5K limit you mentioned.

I'll keep trying and will post back when/if I get TTS working again.

andycitron commented 5 years ago

OK, To work around my TTS credentials problem, I used a non-Watson TTS package and now my ap can talk again. I still get an exception when speaking a long message. I can't be certain its the same one I get when using Watson's TTS, but I suspect it is the same exception.

I'm not certain how to interpret this but it looks like the exception is for Speech to Text. Here's the exception:

error: the speech_to_text service returned an error. message=Session timed out., stack=Error: Session timed out. at emitError (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/watson-developer-cloud/lib/recognize-stream.js:223:23) at W3CWebSocket.socket.onmessage (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/watson-developer-cloud/lib/recognize-stream.js:248:17) at W3CWebSocket._dispatchEvent [as dispatchEvent] (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/yaeti/lib/EventTarget.js:107:17) at W3CWebSocket.onMessage (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/W3CWebSocket.js:234:14) at WebSocketConnection. (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/W3CWebSocket.js:205:19) at emitOne (events.js:96:13) at WebSocketConnection.emit (events.js:188:7) at WebSocketConnection.processFrame (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/WebSocketConnection.js:552:26) at /home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/WebSocketConnection.js:321:40 at _combinedTickCallback (internal/process/next_tick.js:73:7) at process._tickCallback (internal/process/next_tick.js:104:9), type=message, isTrusted=false, _yaeti=true, data={ "error": "Session timed out." }, , addEventListener=function _addEventListener(type, newListener) { var listenersType, i, listener;

if (!type || !newListener) {
    return;
}

listenersType = this._listeners[type];
if (listenersType === undefined) {
    this._listeners[type] = listenersType = [];
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (listener === newListener) {
        return;
    }
}

listenersType.push(newListener);

}, removeEventListener=function _removeEventListener(type, oldListener) { var listenersType, i, listener;

if (!type || !oldListener) {
    return;
}

listenersType = this._listeners[type];
if (listenersType === undefined) {
    return;
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (listener === oldListener) {
        listenersType.splice(i, 1);
        break;
    }
}

if (listenersType.length === 0) {
    delete this._listeners[type];
}

}, dispatchEvent=function _dispatchEvent(event) { var type, listenersType, dummyListener, stopImmediatePropagation = false, i, listener;

if (!event || typeof event.type !== 'string') {
    throw new Error('`event` must have a valid `type` property');
}

// Do some stuff to emulate DOM Event behavior (just if this is not a
// DOM Event object)
if (event._yaeti) {
    event.target = this;
    event.cancelable = true;
}

// Attempt to override the stopImmediatePropagation() method
try {
    event.stopImmediatePropagation = function () {
        stopImmediatePropagation = true;
    };
} catch (error) {}

type = event.type;
listenersType = (this._listeners[type] || []);

dummyListener = this['on' + type];
if (typeof dummyListener === 'function') {
    dummyListener.call(this, event);
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (stopImmediatePropagation) {
        break;
    }

    listener.call(this, event);
}

return !event.defaultPrevented;

}, _url=wss://stream.watsonplatform.net/speech-to-text/api/v1/recognize?model=en-US_BroadbandModel, _readyState=1, _protocol=undefined, _extensions=[], _bufferedAmount=0, _binaryType=arraybuffer, _debug=function debug() { // disabled? if (!debug.enabled) return;

var self = debug;

// set `diff` timestamp
var curr = +new Date();
var ms = curr - (prevTime || curr);
self.diff = ms;
self.prev = prevTime;
self.curr = curr;
prevTime = curr;

// turn the `arguments` into a proper Array
var args = new Array(arguments.length);
for (var i = 0; i < args.length; i++) {
  args[i] = arguments[i];
}

args[0] = exports.coerce(args[0]);

if ('string' !== typeof args[0]) {
  // anything else let's inspect with %O
  args.unshift('%O');
}

// apply any `formatters` transformations
var index = 0;
args[0] = args[0].replace(/%([a-zA-Z%])/g, function(match, format) {
  // if we encounter an escaped % then don't increase the array index
  if (match === '%%') return match;
  index++;
  var formatter = exports.formatters[format];
  if ('function' === typeof formatter) {
    var val = args[index];
    match = formatter.call(self, val);

    // now we need to remove `args[index]` since it's inlined in the `format`
    args.splice(index, 1);
    index--;
  }
  return match;
});

// apply env-specific formatting (colors, etc.)
exports.formatArgs.call(self, args);

var logFn = debug.log || exports.log || console.log.bind(console);
logFn.apply(self, args);

}, domain=null, newListener=function (ev) { if (ev === 'ping'){ this._pingListenerCount++; } }, removeListener=function (ev) { if (ev === 'ping') { this._pingListenerCount--; } }, close=function (code, reason) { onClose.call(self, code, reason); }, message=function (msg) { onMessage.call(self, msg); }, _eventsCount=4, _maxListeners=undefined, _pingListenerCount=0, maxReceivedFrameSize=1048576, maxReceivedMessageSize=8388608, fragmentOutgoingMessages=true, fragmentationThreshold=16384, webSocketVersion=13, assembleFragments=true, disableNagleAlgorithm=true, closeTimeout=5000, , pipe=null, , singleUse=true, isServer=false, requestCert=true, rejectUnauthorized=true, session=undefined, NPNProtocols=undefined, ALPNProtocols=undefined, requestOCSP=undefined, _secureEstablished=true, _securePending=false, _newSessionPending=false, _controlReleased=true, _SNICallback=null, servername=null, npnProtocol=undefined, alpnProtocol=false, authorized=true, authorizationError=null, encrypted=true, close=[function () { // Make sure we are not doing it on OpenSSL's stack setImmediate(destroySSL, this); res = null; }, function g() { target.removeListener(type, g); if (!fired) { fired = true; listener.apply(target, arguments); } }, function () { [native code] }], end=[function g() { target.removeListener(type, g); if (!fired) { fired = true; listener.apply(target, arguments); } }, function () { [native code] }], finish=function onSocketFinish() { // If still connecting - defer handling 'finish' until 'connect' will happen if (this.connecting) { debug('osF: not yet connected'); return this.once('connect', onSocketFinish); }

debug('onSocketFinish'); if (!this.readable || this._readableState.ended) { debug('oSF: ended, destroy', this._readableState); return this.destroy(); }

debug('oSF: not ended, call shutdown()');

// otherwise, just shutdown, or destroy() if not possible if (!this._handle || !this._handle.shutdown) return this.destroy();

var req = new ShutdownWrap(); req.oncomplete = afterShutdown; req.handle = this._handle; var err = this._handle.shutdown(req);

if (err) return this._destroy(errnoException(err, 'shutdown')); }, _socketEnd=function onSocketEnd() { // XXX Should not have to do as much in this function. // ended should already be true, since this is called after // the EOF errno and onread has eof'ed debug('onSocketEnd', this._readableState); this._readableState.ended = true; if (this._readableState.endEmitted) { this.readable = false; maybeDestroy(this); } else { this.once('end', function() { this.readable = false; maybeDestroy(this); }); this.read(0); }

if (!this.allowHalfOpen) { this.write = writeAfterFIN; this.destroySoon(); } }, secure=function () { // Check the size of DHE parameter above minimum requirement // specified in options. var ekeyinfo = socket.getEphemeralKeyInfo(); if (ekeyinfo.type === 'DH' && ekeyinfo.size < options.minDHSize) { var err = new Error('DH parameter size ' + ekeyinfo.size + ' is less than ' + options.minDHSize); socket.emit('error', err); socket.destroy(); return; }

var verifyError = socket._handle.verifyError();

// Verify that server's identity matches it's certificate's names
// Unless server has resumed our existing session
if (!verifyError && !socket.isSessionReused()) {
  var cert = socket.getPeerCertificate();
  verifyError = options.checkServerIdentity(hostname, cert);
}

if (verifyError) {
  socket.authorized = false;
  socket.authorizationError = verifyError.code || verifyError.message;

  if (options.rejectUnauthorized) {
    socket.destroy(verifyError);
    return;
  } else {
    socket.emit('secureConnect');
  }
} else {
  socket.authorized = true;
  socket.emit('secureConnect');
}

// Uncork incoming data
socket.removeListener('end', onHangUp);

}, drain=[function ondrain() { if (this._httpMessage) this._httpMessage.emit('drain'); }, function () { [native code] }], error=function () { [native code] }, pause=function () { [native code] }, resume=function () { [native code] }, data=function () { [native code] }, _eventsCount=10, connecting=false, _hadError=false, reading=true, $ref=$["raw"]["target"]["_connection"]["socket"], onread=null, onconnection=null, writeQueueSize=0, _parentWrap=undefined, $ref=$["raw"]["target"]["_connection"]["socket"]["_tlsOptions"]["secureContext"], reading=true, $ref=$["raw"]["target"]["_connection"]["socket"], onread=function onread(nread, buffer) { var handle = this; var self = handle.owner; assert(handle === self._handle, 'handle != self._handle');

self._unrefTimer();

debug('onread', nread);

if (nread > 0) { debug('got data');

// read success.
// In theory (and in practice) calling readStop right now
// will prevent this from being called again until _read() gets
// called again.

// Optimization: emit the original buffer with end points
var ret = self.push(buffer);

if (handle.reading && !ret) {
  handle.reading = false;
  debug('readStop');
  var err = handle.readStop();
  if (err)
    self._destroy(errnoException(err, 'read'));
}
return;

}

// if we didn't get any bytes, that doesn't necessarily mean EOF. // wait for the next one. if (nread === 0) { debug('not any data, keep waiting'); return; }

// Error, possibly EOF. if (nread !== uv.UV_EOF) { return self._destroy(errnoException(nread, 'read')); }

debug('EOF');

// push a null to signal the end of data. // Do it before maybeDestroy for correct order of events: // end -> close self.push(null);

if (self._readableState.length === 0) { self.readable = false; maybeDestroy(self); }

// internal end event so that we know that the actual socket // is no longer readable, and we can start the shutdown // procedure. No need to wait for all the data to be consumed. self.emit('_socketEnd'); }, writeQueueSize=35, onhandshakestart=function () {}, onhandshakedone=() => this._finishInit(), onocspresponse=(resp) => onocspresponse.call(this, resp), onerror=function (err) { if (self._writableState.errorEmitted) return;

// Destroy socket if error happened before handshake's finish
if (!self._secureEstablished) {
  // When handshake fails control is not yet released,
  // so self._tlsError will return null instead of actual error
  self.destroy(err);
} else if (options.isServer &&
           rejectUnauthorized &&
           /peer did not return a certificate/.test(err.message)) {
  // Ignore server's authorization errors
  self.destroy();
} else {
  // Throw error
  self._emitTLSError(err);
}

self._writableState.errorEmitted = true;

}, _parent=null, _host=stream.watsonplatform.net, objectMode=false, highWaterMark=16384, head=null, tail=null, length=0, length=0, pipes=null, pipesCount=0, flowing=true, ended=false, endEmitted=false, reading=true, sync=false, needReadable=true, emittedReadable=false, readableListening=false, resumeScheduled=false, defaultEncoding=utf8, ranOut=false, awaitDrain=0, readingMore=true, decoder=null, encoding=null, readable=true, domain=null, _maxListeners=undefined, objectMode=false, highWaterMark=16384, needDrain=false, ending=false, ended=false, finished=false, decodeStrings=false, defaultEncoding=utf8, length=6, writing=true, corked=0, sync=false, bufferProcessing=false, onwrite=function (er) { onwrite(stream, er); }, writecb=function nop() {}, writelen=6, bufferedRequest=null, lastBufferedRequest=null, pendingcb=1, prefinished=false, errorEmitted=false, bufferedRequestCount=0, next=null, entry=null, finish=(err) => { var entry = this.entry; this.entry = null; while (entry) { var cb = entry.callback; state.pendingcb--; cb(err); entry = entry.next; } if (state.corkedRequestsFree) { state.corkedRequestsFree.next = this; } else { state.corkedRequestsFree = this; } }, entry=null, finish=(err) => { var entry = this.entry; this.entry = null; while (entry) { var cb = entry.callback; state.pendingcb--; cb(err); entry = entry.next; } if (state.corkedRequestsFree) { state.corkedRequestsFree.next = this; } else { state.corkedRequestsFree = this; } }, writable=true, allowHalfOpen=false, destroyed=false, _bytesDispatched=5384970, _sockname=null, _pendingData=null, _pendingEncoding=, server=undefined, _server=null, $ref=$["raw"]["target"]["_connection"]["socket"]["_handle"], _requestCert=true, _rejectUnauthorized=true, parser=null, _httpMessage=null, read=function (n) { debug('read', n); n = parseInt(n, 10); var state = this._readableState; var nOrig = n;

if (n !== 0) state.emittedReadable = false;

// if we're doing read(0) to trigger a readable event, but we // already have a bunch of data in the buffer, then just trigger // the 'readable' event and move on. if (n === 0 && state.needReadable && (state.length >= state.highWaterMark || state.ended)) { debug('read: emitReadable', state.length, state.ended); if (state.length === 0 && state.ended) endReadable(this); else emitReadable(this); return null; }

n = howMuchToRead(n, state);

// if we've ended, and we're now clear, then finish it up. if (n === 0 && state.ended) { if (state.length === 0) endReadable(this); return null; }

// All the actual chunk generation logic needs to be // below the call to _read. The reason is that in certain // synthetic stream cases, such as passthrough streams, _read // may be a completely synchronous operation which may change // the state of the read buffer, providing enough data when // before there was not enough. // // So, the steps are: // 1. Figure out what the state of things will be after we do // a read from the buffer. // // 2. If that resulting state will trigger a _read, then call _read. // Note that this may be asynchronous, or synchronous. Yes, it is // deeply ugly to write APIs this way, but that still doesn't mean // that the Readable class should behave improperly, as streams are // designed to be sync/async agnostic. // Take note if the _read call is sync or async (ie, if the read call // has returned yet), so that we know whether or not it's safe to emit // 'readable' etc. // // 3. Actually pull the requested chunks out of the buffer and return.

// if we need a readable event, then we need to do some reading. var doRead = state.needReadable; debug('need readable', doRead);

// if we currently have less than the highWaterMark, then also read some if (state.length === 0 || state.length - n < state.highWaterMark) { doRead = true; debug('length less than watermark', doRead); }

// however, if we've ended, then there's no point, and if we're already // reading, then it's unnecessary. if (state.ended || state.reading) { doRead = false; debug('reading or ended', doRead); } else if (doRead) { debug('do read'); state.reading = true; state.sync = true; // if the length is currently zero, then we need a readable event. if (state.length === 0) state.needReadable = true; // call internal read method this._read(state.highWaterMark); state.sync = false; // If _read pushed data synchronously, then reading will be false, // and we need to re-evaluate how much data we can return to the user. if (!state.reading) n = howMuchToRead(nOrig, state); }

var ret; if (n > 0) ret = fromList(n, state); else ret = null;

if (ret === null) { state.needReadable = true; n = 0; } else { state.length -= n; }

if (state.length === 0) { // If we have nothing in the buffer, then we want to know // as soon as we do get something into the buffer. if (!state.ended) state.needReadable = true;

// If we tried to read() past the EOF, then emit end on the next tick.
if (nOrig !== n && state.ended)
  endReadable(this);

}

if (ret !== null) this.emit('data', ret);

return ret; }, _consuming=true, address=169.48.115.62, family=IPv4, port=443, _idleNext=null, _idlePrev=null, _idleTimeout=-1, protocol=undefined, $ref=$["raw"]["target"]["_extensions"], remoteAddress=169.48.115.62, closeReasonCode=-1, closeDescription=null, closeEventEmitted=false, maskOutgoingPackets=true, 0=236, 1=24, 2=108, 3=241, 0=129, 1=36, 2=1, 3=6, 4=0, 5=32, 6=32, 7=32, 8=80, 9=237, domain=null, , _eventsCount=0, _maxListeners=undefined, encoding=undefined, construct=function Buffer(arg, encodingOrOffset, length) { // Common case. if (typeof arg === 'number') { if (typeof encodingOrOffset === 'string') { throw new Error( 'If encoding is specified then the first argument must be a string' ); } return Buffer.allocUnsafe(arg); } return Buffer.from(arg, encodingOrOffset, length); }, length=0, write=function (buf) { if (!head.buffer) { head.buffer = buf; last = head; } else { last.next = { next : null, buffer : buf }; last = last.next; } length += buf.length; self.emit('write', buf); return true; }, end=function (buf) { if (Buffer.isBuffer(buf)) self.write(buf); }, push=function () { var args = [].concat.apply([], arguments); args.forEach(self.write); return self; }, forEach=function (fn) { if (!head.buffer) return new self.construct(0);

    if (head.buffer.length - offset <= 0) return self;
    var firstBuf = head.buffer.slice(offset);

    var b = { buffer : firstBuf, next : head.next };

    while (b && b.buffer) {
        var r = fn(b.buffer);
        if (r) break;
        b = b.next;
    }

    return self;
}, join=function (start, end) {
    if (!head.buffer) return new self.construct(0);
    if (start == undefined) start = 0;
    if (end == undefined) end = self.length;

    var big = new self.construct(end - start);
    var ix = 0;
    self.forEach(function (buffer) {
        if (start < (ix + buffer.length) && ix < end) {
            // at least partially contained in the range
            buffer.copy(
                big,
                Math.max(0, ix - start),
                Math.max(0, start - ix),
                Math.min(buffer.length, end - ix)
            );
        }
        ix += buffer.length;
        if (ix > end) return true; // stop processing past end
    });

    return big;
}, joinInto=function (targetBuffer, targetStart, sourceStart, sourceEnd) {
    if (!head.buffer) return new self.construct(0);
    if (sourceStart == undefined) sourceStart = 0;
    if (sourceEnd == undefined) sourceEnd = self.length;

    var big = targetBuffer;
    if (big.length - targetStart < sourceEnd - sourceStart) {
        throw new Error("Insufficient space available in target Buffer.");
    }
    var ix = 0;
    self.forEach(function (buffer) {
        if (sourceStart < (ix + buffer.length) && ix < sourceEnd) {
            // at least partially contained in the range
            buffer.copy(
                big,
                Math.max(targetStart, targetStart + ix - sourceStart),
                Math.max(0, sourceStart - ix),
                Math.min(buffer.length, sourceEnd - ix)
            );
        }
        ix += buffer.length;
        if (ix > sourceEnd) return true; // stop processing past end
    });

    return big;
}, advance=function (n) {
    offset += n;
    length -= n;
    while (head.buffer && offset >= head.buffer.length) {
        offset -= head.buffer.length;
        head = head.next
            ? head.next
            : { buffer : null, next : null }
        ;
    }
    if (head.buffer === null) last = { next : null, buffer : null };
    self.emit('advance', n);
    return self;
}, take=function (n, encoding) {
    if (n == undefined) n = self.length;
    else if (typeof n !== 'number') {
        encoding = n;
        n = self.length;
    }
    var b = head;
    if (!encoding) encoding = self.encoding;
    if (encoding) {
        var acc = '';
        self.forEach(function (buffer) {
            if (n <= 0) return true;
            acc += buffer.toString(
                encoding, 0, Math.min(n,buffer.length)
            );
            n -= buffer.length;
        });
        return acc;
    } else {
        // If no 'encoding' is specified, then return a Buffer.
        return self.join(0, n);
    }
}, toString=function () {
    return self.take('binary');
}, $ref=$["raw"]["target"]["_connection"]["maskBytes"], $ref=$["raw"]["target"]["_connection"]["frameHeader"], $ref=$["raw"]["target"]["_connection"]["config"], maxReceivedFrameSize=1048576, protocolError=false, frameTooLarge=false, invalidCloseFrameLength=false, parseState=1, closeStatus=-1, fragmentationSize=0, frameQueue=[], connected=true, state=open, waitingForCloseResponse=false, receivedEnd=false, closeTimeout=5000, assembleFragments=true, maxReceivedMessageSize=8388608, outputBufferFull=false, inputPaused=false, receivedDataHandler=function () { [native code] }, _closeTimerHandler=function () { [native code] }, webSocketVersion=13, domain=null, connect=function (connection) {
    onConnect.call(self, connection);
}, connectFailed=function () {
    onConnectFailed.call(self);
}, _eventsCount=2, _maxListeners=undefined, $ref=$["raw"]["target"]["_connection"]["config"], _req=null, protocols=[], origin=null, protocol=wss:, slashes=true, auth=null, host=stream.watsonplatform.net, port=443, hostname=stream.watsonplatform.net, hash=null, search=?model=en-US_BroadbandModel, query=model=en-US_BroadbandModel, pathname=/speech-to-text/api/v1/recognize, path=/speech-to-text/api/v1/recognize?model=en-US_BroadbandModel, href=wss://stream.watsonplatform.net/speech-to-text/api/v1/recognize?model=en-US_BroadbandModel, secure=true, base64nonce=Fll3MqMV5Q1hCiBVXNl/gg==, $ref=$["raw"]["target"]["_connection"]["socket"], objectMode=false, highWaterMark=16384, head=null, tail=null, length=0, length=0, pipes=null, pipesCount=0, flowing=null, ended=true, endEmitted=false, reading=false, sync=true, needReadable=false, emittedReadable=true, readableListening=false, resumeScheduled=false, defaultEncoding=utf8, ranOut=false, awaitDrain=0, readingMore=true, decoder=null, encoding=null, readable=true, domain=null, , _eventsCount=0, _maxListeners=undefined, $ref=$["raw"]["target"]["_connection"]["socket"], $ref=$["raw"]["target"]["_connection"]["socket"], httpVersionMajor=1, httpVersionMinor=1, httpVersion=1.1, complete=true, connection=Upgrade, sec-websocket-accept=NAUfoj1wd/Ydh7DaxES4ilAdZfk=, date=Fri, 10 Aug 2018 16:26:54 GMT, server=-, set-cookie=[Watson-DPAT=e7lEFEI8bZYuTFfw2ZtDV0yjTDMAx7ge574KhHifVxMj%2B4G390Vq3sZrYcuGjcPKz69rgPJx3fCFM2Hq4yaKcfxIZwHhzifbd183VyEFbJEmpxV8kDrNQ5bsOkQk8q9ZedOZZtvXqK3PxCgSB8oPda4kTDEp3UF4BQoR06vj7kuyWAuTvMxyvGAY3%2FcXIpOsUBX%2Fmh6vey%2FmUhX3rlV4XfHUd%2B6gycYTgn%2BoKLLYV2xBi1PS8a0W4wcOKCdZesnpHRhbDfHKNHzDQvw%2FMP4JxqQig8PJtpvc9mJbXPkGjpGsiXQ9%2Fi3IxBEb5HbJ%2FusqJS4MGI6UcO6yng34MYDKWelEnb%2BujfcpyOrrnhMbt5yls0sHHBQJce5xit%2BjjTa28Tnfdi4iSUg9YADiyVDKNXdLLK2epFTqwvEKdJaqMmvPCyWZF%2B9G4xyHLrGw3ZpQQPEukUVEYJ6lZARpUyn7%2FMBzEqcS7i54bSo3HW9geQBdc03Us1cj7cIRhj%2BmiD4cDtzyuT%2FUTZb25LUdlJYlp4nPVYoqcEYb5uAwQsJ5rnTks%2BVXIeu3uejRlm0uCy%2FrHE73Ri4FZij7pZT3ZY8J5uE4X6VtAL6IV2iELP2iQoGU49RR5zaCQ2j9t2NOZBGpuk8R%2B2crZ8BHP49r%2BJUhCnQzvBUMEtoYxNKPJeKzl16ydNCuHMOBZ3opLW%2FDCwehh8NW75NyYJpqslaYXPyb7avpy6txvZvLmAz%2BOzKB9sGhnKKZ0AohdzTpCaa%2Fs%2FkI%2F8RpzxSxVUf3azgOC%2B%2FbQmLDM0BqOd3oNpCbtzaZqtHbOnrTvhwYgHnmcsqS2HMkmIOSYhAFC6PGit8TNCdVl43rRdtJkIaR%2BkUfuGladxUCwmjLlzqo0%2B9%2FG%2Flu4MaokyDaLH5E07kNqgvl00gDONAV%2F1CRdyMROBaF59TMWNeczXi9C5v81%2BQSNpzrl0lFvkIikgpyQK%2FFGOXuSg4QbQ%3D%3D; path=/speech-to-text/api; secure; HttpOnly], x-global-transaction-id=7a6c26455b6dbcce0d5914bf, strict-transport-security=max-age=31536000;, x-dp-watson-tran-id=stream02-223941823, upgrade=websocket, rawHeaders=[Connection, Upgrade, Sec-WebSocket-Accept, NAUfoj1wd/Ydh7DaxES4ilAdZfk=, Date, Fri, 10 Aug 2018 16:26:54 GMT, Server, -, Set-Cookie, Watson-DPAT=e7lEFEI8bZYuTFfw2ZtDV0yjTDMAx7ge574KhHifVxMj%2B4G390Vq3sZrYcuGjcPKz69rgPJx3fCFM2Hq4yaKcfxIZwHhzifbd183VyEFbJEmpxV8kDrNQ5bsOkQk8q9ZedOZZtvXqK3PxCgSB8oPda4kTDEp3UF4BQoR06vj7kuyWAuTvMxyvGAY3%2FcXIpOsUBX%2Fmh6vey%2FmUhX3rlV4XfHUd%2B6gycYTgn%2BoKLLYV2xBi1PS8a0W4wcOKCdZesnpHRhbDfHKNHzDQvw%2FMP4JxqQig8PJtpvc9mJbXPkGjpGsiXQ9%2Fi3IxBEb5HbJ%2FusqJS4MGI6UcO6yng34MYDKWelEnb%2BujfcpyOrrnhMbt5yls0sHHBQJce5xit%2BjjTa28Tnfdi4iSUg9YADiyVDKNXdLLK2epFTqwvEKdJaqMmvPCyWZF%2B9G4xyHLrGw3ZpQQPEukUVEYJ6lZARpUyn7%2FMBzEqcS7i54bSo3HW9geQBdc03Us1cj7cIRhj%2BmiD4cDtzyuT%2FUTZb25LUdlJYlp4nPVYoqcEYb5uAwQsJ5rnTks%2BVXIeu3uejRlm0uCy%2FrHE73Ri4FZij7pZT3ZY8J5uE4X6VtAL6IV2iELP2iQoGU49RR5zaCQ2j9t2NOZBGpuk8R%2B2crZ8BHP49r%2BJUhCnQzvBUMEtoYxNKPJeKzl16ydNCuHMOBZ3opLW%2FDCwehh8NW75NyYJpqslaYXPyb7avpy6txvZvLmAz%2BOzKB9sGhnKKZ0AohdzTpCaa%2Fs%2FkI%2F8RpzxSxVUf3azgOC%2B%2FbQmLDM0BqOd3oNpCbtzaZqtHbOnrTvhwYgHnmcsqS2HMkmIOSYhAFC6PGit8TNCdVl43rRdtJkIaR%2BkUfuGladxUCwmjLlzqo0%2B9%2FG%2Flu4MaokyDaLH5E07kNqgvl00gDONAV%2F1CRdyMROBaF59TMWNeczXi9C5v81%2BQSNpzrl0lFvkIikgpyQK%2FFGOXuSg4QbQ%3D%3D; path=/speech-to-text/api; secure; HttpOnly, X-Global-Transaction-ID, 7a6c26455b6dbcce0d5914bf, Strict-Transport-Security, max-age=31536000;, X-DP-Watson-Tran-ID, stream02-223941823, Upgrade, websocket], , rawTrailers=[], upgrade=true, url=, method=null, statusCode=101, statusMessage=Switching Protocols, $ref=$["raw"]["target"]["_connection"]["socket"], _consuming=false, _dumped=false, firstDataChunk=null, onerror=function (event) {
        self.listening = false;
        var err = new Error('WebSocket connection error');
        err.name = RecognizeStream.WEBSOCKET_CONNECTION_ERROR;
        err['event'] = event;
        self.emit('error', err);
        self.push(null);
    }, onopen=function () {
        self.sendJSON(openingMessage);
        /**
         * emitted once the WebSocket connection has been established
         * @event RecognizeStream#open
         */
        self.emit('open');
    }, onclose=function (e) {
        self.listening = false;
        self.push(null);
        /**
         * @event RecognizeStream#close
         * @param {Number} reasonCode
         * @param {String} description
         */
        self.emit('close', e.code, e.reason);
    }, onmessage=function (frame) {
        if (typeof frame.data !== 'string') {
            return emitError('Unexpected binary data received from server', frame);
        }
        var data;
        try {
            data = JSON.parse(frame.data);
        }
        catch (jsonEx) {
            return emitError('Invalid JSON received from service:', frame, jsonEx);
        }
        /**
         * Emit any messages received over the wire, mainly used for debugging.
         *
         * @event RecognizeStream#message
         * @param {Object} message - frame object with a data attribute that's either a string or a Buffer/TypedArray
         * @param {Object} [data] - parsed JSON object (if possible);
         */
        self.emit('message', frame, data);
        if (data.error) {
            emitError(data.error, frame);
        }
        else if (data.state === 'listening') {
            // this is emitted both when the server is ready for audio, and after we send the close message to indicate that it's done processing
            if (self.listening) {
                self.listening = false;
                socket.close();
            }
            else {
                self.listening = true;
                /**
                 * Emitted when the Watson Service indicates readiness to transcribe audio. Any audio sent before this point will be buffered until now.
                 * @event RecognizeStream#listening
                 */
                self.emit('listening');
            }
        }
        else {
            if (options.readableObjectMode) {
                /**
                 * Object with interim or final results, possibly including confidence scores, alternatives, and word timing.
                 * @event RecognizeStream#data
                 * @param {Object} data
                 */
                self.push(data);
            }
            else if (Array.isArray(data.results)) {
                data.results.forEach(function (result) {
                    if (result.final && result.alternatives) {
                        /**
                         * Finalized text
                         * @event RecognizeStream#data
                         * @param {String} transcript
                         */
                        self.push(result.alternatives[0].transcript, 'utf8');
                    }
                });
            }
        }
    }, cancelable=true, stopImmediatePropagation=function () {
        stopImmediatePropagation = true;
    }

verbose: TJBot initializing microphone

jweisz commented 5 years ago

The error you included above is from STT. Generally, you'll see that timeout happen when the microphone is silent for a period of time and the STT service disconnects. You can customize that disconnection time via the listen.inactivityTimeout config parameter, which we default to -1 so it should never time out. But, in your message you said something was happening when speaking long messages, which would be the TTS service, not the STT service.

I have a theory -- perhaps the TTS message you're trying to speak is long enough that it causes the STT service to time out? We don't pause listening while TJBot is speaking, but maybe we should?

I'm not sure this will fix things, but it might be worth a shot:

tj.pauseListening();
tj.speak("super long message goes here");
tj.resumeListening();

andycitron commented 5 years ago

I'm pretty sure I had the pauseListening/resumeListening in the code when I generated that stack trace. I do now, for sure. I did see another exception that indicated the speech-to-text was over the max number of characters.

What I think is going on is that the long spoken text is playing asynchronously to the node.js code. So the node.js code goes back into listening mode while its 'talking'. So it hears itself and its talking for a long time.

I'm currently using the 'eSpeak' package for text-to-speech. I'm pretty sure I used up my plan's max TTS and that's why my tjbot TTS credentials are being rejected. For sure eSpeak runs async to my ap. I'm not sure if that is true for .tj.speak(). I think it is, so its likely the same issue for both TTS techniques: its listening while its talking and its talking for long enough that its hitting some STT limit.

How do folks work around this?

jweisz commented 5 years ago

Honestly, I haven't encountered this issue before.. I've had tjbot listening while speaking and it doesn't pick up its "own voice", and I've had tjbot speak some fairly long things. Maybe lowering the speaker volume would help, but I totally understand that's not a satisfactory solution.

I'm also surprised that pauseListening()/resumeListening() aren't helping either, or maybe it is and the issue really is just in your account quota. You can try going to bluemix, deleting your existing STT/TTS services, re-creating them, and getting new credentials. I'm not 100% sure that will reset your quota (I'm assuming you're using the free tier), but its worth a shot.

andycitron commented 5 years ago

For sure my STT and TTS quotas have been reached this month because of the extended speaking/listening/testing I've been doing. So that could be the problem currently. I'm not sure its the 'root' problem. I can't test again until next month when the quota comes back. I'm pretty sure getting new credentials would not get around the quota issue.

I'll close this for now until I get better debug info.

Thanks for attempting to tackle this issue.

andycitron commented 5 years ago

Justin, I was able to gather more information on this issue. It seems the text to speech code is timing out locally when speaking a phrase 417 characters (or more).

Here is some debug info as well as the phrase that was being spoken at the time.

I'm implementing some 'alexa-like functions' such as weather and news. That can return some long phrases that take many seconds to speak.

The system seems to recover fine from the timeout, but it would be nice to avoid the timeout error.

Here's my debug information.

promise exiting I'll check the weather weather promise Success! The weather for Tuesday September 4, 2018 is Partly Cloudy Wind Enorth east 7 miles per hour. Relative humidity is 59%. UV index is 7 out of 10. Weather for Wednesday daytime is Partly cloudy. A stray shower or thunderstorm is possible. High 91 . Winds light and variable. High will be 96. Low will be 71. Weather Wednesday evening is Clear skies. Low 71 . Winds light and variable. High will be 91. Low will be 71. response length 417 verbose: TJBot speaking with voice en-US_MichaelVoice verbose: TJBot speaking: The weather for Tuesday September 4, 2018 is Partly Cloudy Wind Enorth east 7 miles per hour. Relative humidity is 59%. UV index is 7 out of 10. Weather for Wednesday daytime is Partly cloudy. A stray shower or thunderstorm is possible. High 91 . Winds light and variable. High will be 96. Low will be 71. Weather Wednesday evening is Clear skies. Low 71 . Winds light and variable. High will be 91. Low will be 71. ========= { filename: '/tmp/tjbot11884-4474-1brjmt.p7y2dcmcxr', gain: 100, debug: true, player: 'aplay', device: 'plughw:0,0' } error: the speech_to_text service returned an error. message=Session timed out., stack=Error: Session timed out. at emitError (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/watson-developer-cloud/lib/recognize-stream.js:232:23) at W3CWebSocket.socket.onmessage (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/watson-developer-cloud/lib/recognize-stream.js:257:17) at W3CWebSocket._dispatchEvent [as dispatchEvent] (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/yaeti/lib/EventTarget.js:107:17) at W3CWebSocket.onMessage (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/W3CWebSocket.js:234:14) at WebSocketConnection. (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/W3CWebSocket.js:205:19) at emitOne (events.js:96:13) at WebSocketConnection.emit (events.js:188:7) at WebSocketConnection.processFrame (/home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/WebSocketConnection.js:552:26) at /home/pi/Desktop/tjbot/recipes/conversation/node_modules/websocket/lib/WebSocketConnection.js:321:40 at _combinedTickCallback (internal/process/next_tick.js:73:7) at process._tickCallback (internal/process/next_tick.js:104:9), type=message, isTrusted=false, _yaeti=true, data={ "error": "Session timed out." }, , addEventListener=function _addEventListener(type, newListener) { var listenersType, i, listener;

if (!type || !newListener) {
    return;
}

listenersType = this._listeners[type];
if (listenersType === undefined) {
    this._listeners[type] = listenersType = [];
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (listener === newListener) {
        return;
    }
}

listenersType.push(newListener);

}, removeEventListener=function _removeEventListener(type, oldListener) { var listenersType, i, listener;

if (!type || !oldListener) {
    return;
}

listenersType = this._listeners[type];
if (listenersType === undefined) {
    return;
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (listener === oldListener) {
        listenersType.splice(i, 1);
        break;
    }
}

if (listenersType.length === 0) {
    delete this._listeners[type];
}

}, dispatchEvent=function _dispatchEvent(event) { var type, listenersType, dummyListener, stopImmediatePropagation = false, i, listener;

if (!event || typeof event.type !== 'string') {
    throw new Error('`event` must have a valid `type` property');
}

// Do some stuff to emulate DOM Event behavior (just if this is not a
// DOM Event object)
if (event._yaeti) {
    event.target = this;
    event.cancelable = true;
}

// Attempt to override the stopImmediatePropagation() method
try {
    event.stopImmediatePropagation = function () {
        stopImmediatePropagation = true;
    };
} catch (error) {}

type = event.type;
listenersType = (this._listeners[type] || []);

dummyListener = this['on' + type];
if (typeof dummyListener === 'function') {
    dummyListener.call(this, event);
}

for (i = 0; !!(listener = listenersType[i]); i++) {
    if (stopImmediatePropagation) {
        break;
    }

    listener.call(this, event);
}

return !event.defaultPrevented;

}, _url=wss://stream.watsonplatform.net/speech-to-text/api/v1/recognize?model=en-US_BroadbandModel, _readyState=1, _protocol=undefined, _extensions=[], _bufferedAmount=0, _binaryType=arraybuffer, _debug=function debug() { // disabled? if (!debug.enabled) return;

var self = debug;

// set `diff` timestamp
var curr = +new Date();
var ms = curr - (prevTime || curr);
self.diff = ms;
self.prev = prevTime;
self.curr = curr;
prevTime = curr;

// turn the `arguments` into a proper Array
var args = new Array(arguments.length);
for (var i = 0; i < args.length; i++) {
  args[i] = arguments[i];
}

args[0] = exports.coerce(args[0]);

if ('string' !== typeof args[0]) {
  // anything else let's inspect with %O
  args.unshift('%O');
}

// apply any `formatters` transformations
var index = 0;
args[0] = args[0].replace(/%([a-zA-Z%])/g, function(match, format) {
  // if we encounter an escaped % then don't increase the array index
  if (match === '%%') return match;
  index++;
  var formatter = exports.formatters[format];
  if ('function' === typeof formatter) {
    var val = args[index];
    match = formatter.call(self, val);

    // now we need to remove `args[index]` since it's inlined in the `format`
    args.splice(index, 1);
    index--;
  }
  return match;
});

// apply env-specific formatting (colors, etc.)
exports.formatArgs.call(self, args);

var logFn = debug.log || exports.log || console.log.bind(console);
logFn.apply(self, args);

}, domain=null, newListener=function (ev) { if (ev === 'ping'){ this._pingListenerCount++; } }, removeListener=function (ev) { if (ev === 'ping') { this._pingListenerCount--; } }, close=function (code, reason) { onClose.call(self, code, reason); }, message=function (msg) { onMessage.call(self, msg); }, _eventsCount=4, _maxListeners=undefined, _pingListenerCount=0, maxReceivedFrameSize=1048576, maxReceivedMessageSize=8388608, fragmentOutgoingMessages=true, fragmentationThreshold=16384, webSocketVersion=13, assembleFragments=true, disableNagleAlgorithm=true, closeTimeout=5000, , pipe=null, , singleUse=true, isServer=false, requestCert=true, rejectUnauthorized=true, session=undefined, NPNProtocols=undefined, ALPNProtocols=undefined, requestOCSP=undefined, _secureEstablished=true, _securePending=false, _newSessionPending=false, _controlReleased=true, _SNICallback=null, servername=null, npnProtocol=undefined, alpnProtocol=false, authorized=true, authorizationError=null, encrypted=true, close=[function () { // Make sure we are not doing it on OpenSSL's stack setImmediate(destroySSL, this); res = null; }, function g() { target.removeListener(type, g); if (!fired) { fired = true; listener.apply(target, arguments); } }, function () { [native code] }], end=[function g() { target.removeListener(type, g); if (!fired) { fired = true; listener.apply(target, arguments); } }, function () { [native code] }], finish=function onSocketFinish() { // If still connecting - defer handling 'finish' until 'connect' will happen if (this.connecting) { debug('osF: not yet connected'); return this.once('connect', onSocketFinish); }

debug('onSocketFinish'); if (!this.readable || this._readableState.ended) { debug('oSF: ended, destroy', this._readableState); return this.destroy(); }

debug('oSF: not ended, call shutdown()');

// otherwise, just shutdown, or destroy() if not possible if (!this._handle || !this._handle.shutdown) return this.destroy();

var req = new ShutdownWrap(); req.oncomplete = afterShutdown; req.handle = this._handle; var err = this._handle.shutdown(req);

if (err) return this._destroy(errnoException(err, 'shutdown')); }, _socketEnd=function onSocketEnd() { // XXX Should not have to do as much in this function. // ended should already be true, since this is called after // the EOF errno and onread has eof'ed debug('onSocketEnd', this._readableState); this._readableState.ended = true; if (this._readableState.endEmitted) { this.readable = false; maybeDestroy(this); } else { this.once('end', function() { this.readable = false; maybeDestroy(this); }); this.read(0); }

if (!this.allowHalfOpen) { this.write = writeAfterFIN; this.destroySoon(); } }, secure=function () { // Check the size of DHE parameter above minimum requirement // specified in options. var ekeyinfo = socket.getEphemeralKeyInfo(); if (ekeyinfo.type === 'DH' && ekeyinfo.size < options.minDHSize) { var err = new Error('DH parameter size ' + ekeyinfo.size + ' is less than ' + options.minDHSize); socket.emit('error', err); socket.destroy(); return; }

var verifyError = socket._handle.verifyError();

// Verify that server's identity matches it's certificate's names
// Unless server has resumed our existing session
if (!verifyError && !socket.isSessionReused()) {
  var cert = socket.getPeerCertificate();
  verifyError = options.checkServerIdentity(hostname, cert);
}

if (verifyError) {
  socket.authorized = false;
  socket.authorizationError = verifyError.code || verifyError.message;

  if (options.rejectUnauthorized) {
    socket.destroy(verifyError);
    return;
  } else {
    socket.emit('secureConnect');
  }
} else {
  socket.authorized = true;
  socket.emit('secureConnect');
}

// Uncork incoming data
socket.removeListener('end', onHangUp);

}, drain=[function ondrain() { if (this._httpMessage) this._httpMessage.emit('drain'); }, function () { [native code] }], error=function () { [native code] }, pause=function () { [native code] }, resume=function () { [native code] }, data=function () { [native code] }, _eventsCount=10, connecting=false, _hadError=false, reading=true, $ref=$["raw"]["target"]["_connection"]["socket"], onread=null, onconnection=null, writeQueueSize=0, _parentWrap=undefined, $ref=$["raw"]["target"]["_connection"]["socket"]["_tlsOptions"]["secureContext"], reading=true, $ref=$["raw"]["target"]["_connection"]["socket"], onread=function onread(nread, buffer) { var handle = this; var self = handle.owner; assert(handle === self._handle, 'handle != self._handle');

self._unrefTimer();

debug('onread', nread);

if (nread > 0) { debug('got data');

// read success.
// In theory (and in practice) calling readStop right now
// will prevent this from being called again until _read() gets
// called again.

// Optimization: emit the original buffer with end points
var ret = self.push(buffer);

if (handle.reading && !ret) {
  handle.reading = false;
  debug('readStop');
  var err = handle.readStop();
  if (err)
    self._destroy(errnoException(err, 'read'));
}
return;

}

// if we didn't get any bytes, that doesn't necessarily mean EOF. // wait for the next one. if (nread === 0) { debug('not any data, keep waiting'); return; }

// Error, possibly EOF. if (nread !== uv.UV_EOF) { return self._destroy(errnoException(nread, 'read')); }

debug('EOF');

// push a null to signal the end of data. // Do it before maybeDestroy for correct order of events: // end -> close self.push(null);

if (self._readableState.length === 0) { self.readable = false; maybeDestroy(self); }

// internal end event so that we know that the actual socket // is no longer readable, and we can start the shutdown // procedure. No need to wait for all the data to be consumed. self.emit('_socketEnd'); }, writeQueueSize=0, onhandshakestart=function () {}, onhandshakedone=() => this._finishInit(), onocspresponse=(resp) => onocspresponse.call(this, resp), onerror=function (err) { if (self._writableState.errorEmitted) return;

// Destroy socket if error happened before handshake's finish
if (!self._secureEstablished) {
  // When handshake fails control is not yet released,
  // so self._tlsError will return null instead of actual error
  self.destroy(err);
} else if (options.isServer &&
           rejectUnauthorized &&
           /peer did not return a certificate/.test(err.message)) {
  // Ignore server's authorization errors
  self.destroy();
} else {
  // Throw error
  self._emitTLSError(err);
}

self._writableState.errorEmitted = true;

}, _parent=null, _host=stream.watsonplatform.net, objectMode=false, highWaterMark=16384, head=null, tail=null, length=0, length=0, pipes=null, pipesCount=0, flowing=true, ended=false, endEmitted=false, reading=true, sync=false, needReadable=true, emittedReadable=false, readableListening=false, resumeScheduled=false, defaultEncoding=utf8, ranOut=false, awaitDrain=0, readingMore=true, decoder=null, encoding=null, readable=true, domain=null, _maxListeners=undefined, objectMode=false, highWaterMark=16384, needDrain=false, ending=false, ended=false, finished=false, decodeStrings=false, defaultEncoding=utf8, length=0, writing=false, corked=0, sync=false, bufferProcessing=false, onwrite=function (er) { onwrite(stream, er); }, writecb=null, writelen=0, bufferedRequest=null, lastBufferedRequest=null, pendingcb=0, prefinished=false, errorEmitted=false, bufferedRequestCount=0, next=null, entry=null, finish=(err) => { var entry = this.entry; this.entry = null; while (entry) { var cb = entry.callback; state.pendingcb--; cb(err); entry = entry.next; } if (state.corkedRequestsFree) { state.corkedRequestsFree.next = this; } else { state.corkedRequestsFree = this; } }, entry=null, finish=(err) => { var entry = this.entry; this.entry = null; while (entry) { var cb = entry.callback; state.pendingcb--; cb(err); entry = entry.next; } if (state.corkedRequestsFree) { state.corkedRequestsFree.next = this; } else { state.corkedRequestsFree = this; } }, writable=true, allowHalfOpen=false, destroyed=false, _bytesDispatched=4722956, _sockname=null, _pendingData=null, _pendingEncoding=, server=undefined, _server=null, $ref=$["raw"]["target"]["_connection"]["socket"]["_handle"], _requestCert=true, _rejectUnauthorized=true, parser=null, _httpMessage=null, read=function (n) { debug('read', n); n = parseInt(n, 10); var state = this._readableState; var nOrig = n;