Never responds again after network error

[nealsanche]

Last night I was working with this, and found once there is a network error, button presses are ignored from that point on. If I can replicate it tonight, I will add an exception trace to this issue, and see if I can see where the code is actually failing.

I found an old USB plantronics headset was sufficient as a single-input single-output device for Audio. This also allows me to talk to the Assistant without anyone else getting too annoyed with me, which is nice. I was pushing the button described in https://github.com/androidthings/sample-button and after only a few tries, sometimes after 20 or so questions answered, the assistant service would throw an exception, and then I'd have to reboot the device.

After reboot, I would have to wait several minutes before the Pi3 board had a correct System Time (it starts off with EPOCH time, Jan 1, 1970) and the SSL connection fails.

Then I'd be able to push the button again for a little while before the first exception would cause the button to become non-responsive.

I'll look into this more, this evening, and add to this report.

[nealsanche]

Here's the stack trace I am seeing:

7-12 01:02:05.824 725-1397/com.example.androidthings.assistant E/AssistantActivity: converse response error: # com.google.rpc.Status@91ef3c9b
                                                                                     code: 14
                                                                                     message: "Service unavailable."
07-12 01:02:06.806 725-1397/com.example.androidthings.assistant E/AssistantActivity: converse error:
                                                                                     io.grpc.StatusRuntimeException: UNKNOWN: Unknown Error.
                                                                                         at io.grpc.Status.asRuntimeException(Status.java:540)
                                                                                         at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:392)
                                                                                         at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:428)
                                                                                         at io.grpc.internal.ClientCallImpl.access$100(ClientCallImpl.java:76)
                                                                                         at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:514)
                                                                                         at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:431)
                                                                                         at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:546)
                                                                                         at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
                                                                                         at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:152)
                                                                                         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
                                                                                         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
                                                                                         at java.lang.Thread.run(Thread.java:761)

[Fleker]

I have encountered this issue occasionally as well, although I don't know how to reproduce reliably.

[proppy]

@nealsanche @Fleker I'm curious if after further button presses will trigger the same error again and again?

Pressing the button again should repost the mStartAssistantRequest Runnable: https://github.com/androidthings/sample-googleassistant/blob/master/app/src/main/java/com/example/androidthings/assistant/AssistantActivity.java#L347

[nealsanche]

Yes the same error happens consistently after the app gets into that state. I have to kill and restart the app to get it functional again.

On Wed, Aug 9, 2017, 6:07 AM Johan Euphrosine notifications@github.com wrote:

@nealsanche https://github.com/nealsanche @Fleker https://github.com/fleker I'm curious if after further button presses will trigger the same error again and again?

Pressing the button again should repost the mStartAssistantRequest Runnable:

https://github.com/androidthings/sample-googleassistant/blob/master/app/src/main/java/com/example/androidthings/assistant/AssistantActivity.java#L347

— You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub https://github.com/androidthings/sample-googleassistant/issues/32#issuecomment-321236424, or mute the thread https://github.com/notifications/unsubscribe-auth/AFHsyakT77Qc43dIpTPHnvcOPnf18Y-Yks5sWaEegaJpZM4OUy2u .

-- *Neal Sanche | Android Tech Lead (c)403.870.2356 (o)888.740.0967*

http://robotsandpencils.com

-- Robots and Pencils Inc | 1507 14th Ave SW Calgary AB T3C 0W4 You can unsubscribe from the Robots and Pencils mailing lists by clicking here. https://robotsandpencils.com/contact/unsubscribe.html

[hpsaturn]

I have the same error, the only different is that I use other mic array board (MATRIX Creator), not voicehat.

My fork: Google Assistant code for MATRIX Creator

Output:

com.example.androidthings.assistant E/AssistantActivity: 
converse response error: # com.google.rpc.Status@91ef3c9b
code: 14
message: "Service unavailable."
com.example.androidthings.assistant E/AssistantActivity: 
converse error:
io.grpc.StatusRuntimeException: UNKNOWN: Unknown Error.
at io.grpc.Status.asRuntimeException(Status.java:540)
at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:392)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:428)
at io.grpc.internal.ClientCallImpl.access$100(ClientCallImpl.java:76)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:514)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:431)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:546)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:152)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
at java.lang.Thread.run(Thread.java:764)

[hpsaturn]

My own answer,

I resolved issue or I found the problem in the implementation on Audio Driver (UserDriver) for my hat (MATRIXCreator), but maybe is similar issue for VoiceHat or USB plantronics headset from @nealsanche. When the audio buffer on read interface implementation below is wrong and it sending maybe empty buffer or a bad ByteBuffer to GRPC service, it reproduce the issue. Maybe the issue or bug on Google Assistant service is a missing message or missing empty buffer detection.

private class AudioInputUserDriver extends AudioInputDriver {
        @Override
        public void onStandbyChanged(boolean b) {
        }

        @Override
        public int read(ByteBuffer byteBuffer, int i) {
            try {
                // VoiceHat => mDevice is I2S device
                // MATRIXCreator => mDevice is custom wishbone device (SPI)
                return mDevice.read(byteBuffer, i); 
            } catch (IOException e) {
                Log.e(TAG, "[MIC] error during read operation:", e);
                return -1;
            }
        }
    }

Details in my fork.

[Fleker]

Did you resolve the issue in your fork, or do you believe you found where the issue may be?

[hpsaturn]

Apparent I resolved the issue in my fork, maybe was it a possible bad audio buffer implementation, but too maybe the GRPC assistant service haven't error messages for bad or empty buffers.

[Fleker]

I looked at your code. Are you still using the VoiceHat driver? I didn't see how your user driver was any different.

[hpsaturn]

No, I don't use VoiceHat hardware, for now I still writing MATRIX Creator user driver, the difference is in the buffer handler and device type:

My extend from InputDriver not use I2S protocol, use SPI handler (micArray class):

    private class AudioInputUserDriver extends AudioInputDriver {

        @Override
        public void onStandbyChanged(boolean b) {
        }

        @Override
        public int read(ByteBuffer byteBuffer, int i) {
            try {
                return micArray.readFromDevice(byteBuffer, i);
            } catch (IOException e) {
                Log.e(TAG, "[MIC] error during readFromDevice operation:", e);
                return -1;
            }
        }
    }

And micArray class implements read buffer like next (see details in MicArray class)

   public int readFromDevice(ByteBuffer byteBuffer, int i) throws IOException {
        if(isReadyData&&!stopService) {
            int oldpos = byteBuffer.position();
            for (int x = 0; x < (i / 2); x++) {
                byteBuffer.putShort(mic0.poll());
            }
            int newpos = byteBuffer.position();
            return newpos - oldpos;
        }
        return 0;
    }

Right now it works fine, but in my first tries maybe my buffer handler was sending a wrong buffer read, and GRPC was fails. I don't know if this, maybe helps a detection of this issue for another devices, like the USB device in thread here.

[championswimmer]

42 isn't the same. The error is different for my case -

io.grpc.StatusRuntimeException: INTERNAL: Received unexpected EOS on DATA frame from server.

[championswimmer]

Using classpath "com.google.protobuf:protobuf-gradle-plugin:0.8.2"

instead of

classpath "com.google.protobuf:protobuf-gradle-plugin:0.8.0"

fixes it for me

[Fleker]

I'll try updating that plugin version and test it myself.