search

snipsco / snips-issues

Feel free to share your bugs with us.
14 stars 5 forks source link

[Android] Intents time out #173

Closed erksch closed 5 years ago

erksch commented 5 years ago

Hey guys! Thanks for the great work on snips!

I am using the snips android demo, not the quickstart, as suggested in this github issue comment.

The android app correctly detects me saying the wakeword and captures text correctly. However, the intentDetectedListener is not called. After some digging in the forum I found that the sessionEndedListener tells the termination reason. The termination type is TIMEOUT. According to this topic in the forum about timeouts on macOS the reason is that snippets are not supported as actions and they can not be run thus timing out. According to this topic answer, code snippets are not supported in android. So I guess it happened that my intent was detected but the action could not be run so the session timed out and that's why the intentDetectedListener is not called.

So I disabled the actions and wanted to code my action logic in Java in the intentDetectedListener instead. But even if the actions are turned off, the listener is not called and the session times out.

If I say something that does not match an intent, I actually get the termination type INTENT NOT RECOGNIZED, so that I get a TIMEOUT instead means that my intent should be detected but times out anyway.

Any thoughts on this?

Also it would be very awesome to add the following information to the docs:

cpoisson commented 5 years ago

Hi @erksch, Regarding the docs, thanks for your feedback, I'll check the quick fix that can be done.

Another remark regarding snippets,

We currently only offer python code snippets relying on MQTT and hermes-python, thus they are not supposed nor designed to run on android.

Regarding OSX, the reason is that snips-template needed to render the scripts from the snippets is not available on MacOS.

Anyway, snippets are not the recommended way to go as a developer, on OSX or on a Pi, the best would be to develop your own action services based on hermes-protocol (python, js) or using MQTT.

The best is to consider that the snips-platform primary goal is to serve as a vocal interface shooting intents with associated datas.

fredszaq commented 5 years ago

Hi @erksch, could you provide logs from the yourappId:snipsProcessingService process on your device ? This would help a lot to understand the problem (make sure to enableLogs on the SnipsPlatformClientBuilder)

erksch commented 5 years ago

Ah yes sorry! Here is a complete log from the processing service while detecting some text that should match one of my intents. 

2019-07-19 13:58:32.507 14826-14873/ai.snips.snipsdemo:snipsProcessingService I/snips_hotword_hermes: Hotword detected: site_id:default model:hey_snips (63ms ago)
2019-07-19 13:58:32.507 14826-14873/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Hotword/HotwordDetected {
        id: "default_hotword",
        message: HotwordDetectedMessage {
            site_id: "default",
            model_id: "hey_snips",
            model_version: Some(
                "workflow-hey_snips_subww_feedback_10seeds-2018_12_04T12_13_05_evaluated_model_0002"
            ),
            model_type: Some(
                Universal
            ),
            current_sensitivity: Some(
                0.5
            ),
            audio_timestamp_ms: Some(
                1563537512443
            )
        }
    }
2019-07-19 13:58:32.508 14826-14880/ai.snips.snipsdemo:snipsProcessingService I/snips_dialogue_lib::c..: Site [default]: reset site -> turn off ASR and turn off Hotword
2019-07-19 13:58:32.508 14826-14880/ai.snips.snipsdemo:snipsProcessingService I/snips_dialogue_lib::c..: Session [b7f7a8eb-407c-483f-9a79-65c7c48f9fb4]: The session has been created because the site "default" is free
2019-07-19 13:58:32.508 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Asr/AsrStopListening {
        site: SiteMessage {
            site_id: "default",
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        }
    }
2019-07-19 13:58:32.508 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Hotword/IdentifiableToggleableToggleOff {
        site: SiteMessage {
            site_id: "default",
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        },
        component: Hotword
    }
2019-07-19 13:58:32.508 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Dialogue/DialogueSessionStarted {
        status: SessionStartedMessage {
            session_id: "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4",
            custom_data: None,
            site_id: "default",
            reactivated_from_session_id: None
        }
    }
2019-07-19 13:58:32.508 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Asr/AsrStartListening {
        site: SiteMessage {
            site_id: "default",
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        }
    }
2019-07-19 13:58:32.510 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_asr_hermes: ignore stop request, already idle
2019-07-19 13:58:32.512 14826-14871/ai.snips.snipsdemo:snipsProcessingService D/snips_hotword_lib::fe..: Clear feature states
2019-07-19 13:58:32.512 14826-14871/ai.snips.snipsdemo:snipsProcessingService I/snips_hotword_lib::au..: Audio thread for site default stopped.
2019-07-19 13:58:32.513 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_hermes: Listening
2019-07-19 13:58:32.513 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0       entered AsrRunner::run
2019-07-19 13:58:32.513 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_asr_lib::asr:          sample rate is 16000
2019-07-19 13:58:32.513 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0+0.000 capture started
2019-07-19 13:58:32.513 14826-14873/ai.snips.snipsdemo:snipsProcessingService D/snips_hotword_lib::un..: Clear network state
2019-07-19 13:58:32.520 14826-14873/ai.snips.snipsdemo:snipsProcessingService D/snips_hotword_lib::un..: Clear post processor
2019-07-19 13:58:35.307 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0+2.795 endpoint detected (rule:4) frame:68 samples:43520 signal_time:2.72 rtf:0.382
2019-07-19 13:58:35.323 14826-14953/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: Source thread stop on push: "Disconnected(..)"
2019-07-19 13:58:35.324 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0+2.811 capture ended
2019-07-19 13:58:35.325 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0+2.812 decoder finalized
2019-07-19 13:58:35.325 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::logs: Sausage decoding : 0.3 0.5
2019-07-19 13:58:35.326 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: Postprocessing 'olaf hat ein glas wasser getrunken'
2019-07-19 13:58:35.326 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`INTENT`7113c58f-24f2-4606-8464-d611d43f3031`START (.*?) `INTENT`7113c58f-24f2-4606-8464-d611d43f3031`END/$1/ : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.326 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`INTENT`7113c58f-24f2-4606-8464-d611d43f3031`START // : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.326 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`INTENT`16e24047-e49d-44b0-b2bb-4fc76da09100`START (.*?) `INTENT`16e24047-e49d-44b0-b2bb-4fc76da09100`END/$1/ : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.326 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`INTENT`16e24047-e49d-44b0-b2bb-4fc76da09100`START // : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`ENTITY`ea5651b5-dd19-4141-a75c-6be7d4bd15ae`START (.*?) `ENTITY`ea5651b5-dd19-4141-a75c-6be7d4bd15ae`END/$1/ : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`ENTITY`ea5651b5-dd19-4141-a75c-6be7d4bd15ae`START // : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`ENTITY`af6a73e2-db35-4ac8-b833-a56edf9e847c`START (.*?) `ENTITY`af6a73e2-db35-4ac8-b833-a56edf9e847c`END/$1/ : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: PostProcessor s/`ENTITY`af6a73e2-db35-4ac8-b833-a56edf9e847c`START // : olaf hat ein glas wasser getrunken -> olaf hat ein glas wasser getrunken
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_lib::asr: T0+2.814 lookup and post-processing done
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Asr/AsrTextCaptured {
        text_captured: TextCapturedMessage {
            text: "olaf hat ein glas wasser getrunken",
            likelihood: 1.0,
            tokens: Some(
                [
                    AsrToken {
                        value: "olaf",
                        confidence: 1.0,
                        range_start: 0,
                        range_end: 4,
                        time: AsrDecodingDuration {
                            start: 0.0,
                            end: 0.65999997
                        }
                    },
                    AsrToken {
                        value: "hat",
                        confidence: 1.0,
                        range_start: 5,
                        range_end: 8,
                        time: AsrDecodingDuration {
                            start: 0.65999997,
                            end: 0.81
                        }
                    },
                    AsrToken {
                        value: "ein",
                        confidence: 1.0,
                        range_start: 9,
                        range_end: 12,
                        time: AsrDecodingDuration {
                            start: 0.81,
                            end: 0.81
                        }
                    },
                    AsrToken {
                        value: "glas",
                        confidence: 1.0,
                        range_start: 13,
                        range_end: 17,
                        time: AsrDecodingDuration {
                            start: 0.81,
                            end: 1.0799999
                        }
                    },
                    AsrToken {
                        value: "wasser",
                        confidence: 1.0,
                        range_start: 18,
                        range_end: 24,
                        time: AsrDecodingDuration {
                            start: 1.0799999,
                            end: 1.29
                        }
                    },
                    AsrToken {
                        value: "getrunken",
                        confidence: 1.0,
                        range_start: 25,
                        range_end: 34,
                        time: AsrDecodingDuration {
                            start: 1.29,
                            end: 2.52
                        }
                    }
                ]
            ),
            seconds: 2.0,
            site_id: "default",
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        }
    }
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_hermes: Cleanup
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_hermes: Preparing decoder
2019-07-19 13:58:35.327 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::decode::..: Decoder started with decoder config DecoderConfig { beam_size: 12.0, max_active: 2500, min_active: 200, lattice_beam_size: 4.0, acoustic_scale: 0.8, use_final_probs: true, mbr_config: Some(MbrConfig { unk_threshold: 0.3, unk_proba: 0.5 }) } and endpointing rules EndpointingConfiguration { container: {"rule4": EndpointingRule { must_contain_nonsilence: true, min_trailing_silence: 0.5, max_relative_cost: 2.5, min_utterance_length: 0.0 }, "rule3": EndpointingRule { must_contain_nonsilence: true, min_trailing_silence: 1.0, max_relative_cost: 8.0, min_utterance_length: 0.0 }, "rule2": EndpointingRule { must_contain_nonsilence: true, min_trailing_silence: 0.7, max_relative_cost: 5.5, min_utterance_length: 0.0 }, "rule1": EndpointingRule { must_contain_nonsilence: false, min_trailing_silence: 4.0, max_relative_cost: 10000000000.0, min_utterance_length: 0.0 }, "rule5": EndpointingRule { must_contain_nonsilence: false, min_trailing_silence: 0.0, max_relative_cost: 10000000000.0, min_utterance_length: 10.0 }} }
2019-07-19 13:58:35.329 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Asr/AsrStopListening {
        site: SiteMessage {
            site_id: "default",
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        }
    }
2019-07-19 13:58:35.332 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Nlu/NluQuery {
        query: NluQueryMessage {
            input: "olaf hat ein glas wasser getrunken",
            asr_tokens: Some(
                [
                    AsrToken {
                        value: "olaf",
                        confidence: 1.0,
                        range_start: 0,
                        range_end: 4,
                        time: AsrDecodingDuration {
                            start: 0.0,
                            end: 0.65999997
                        }
                    },
                    AsrToken {
                        value: "hat",
                        confidence: 1.0,
                        range_start: 5,
                        range_end: 8,
                        time: AsrDecodingDuration {
                            start: 0.65999997,
                            end: 0.81
                        }
                    },
                    AsrToken {
                        value: "ein",
                        confidence: 1.0,
                        range_start: 9,
                        range_end: 12,
                        time: AsrDecodingDuration {
                            start: 0.81,
                            end: 0.81
                        }
                    },
                    AsrToken {
                        value: "glas",
                        confidence: 1.0,
                        range_start: 13,
                        range_end: 17,
                        time: AsrDecodingDuration {
                            start: 0.81,
                            end: 1.0799999
                        }
                    },
                    AsrToken {
                        value: "wasser",
                        confidence: 1.0,
                        range_start: 18,
                        range_end: 24,
                        time: AsrDecodingDuration {
                            start: 1.0799999,
                            end: 1.29
                        }
                    },
                    AsrToken {
                        value: "getrunken",
                        confidence: 1.0,
                        range_start: 25,
                        range_end: 34,
                        time: AsrDecodingDuration {
                            start: 1.29,
                            end: 2.52
                        }
                    }
                ]
            ),
            intent_filter: None,
            id: Some(
                "793edd7f-ff19-493d-9b57-a8028e528056"
            ),
            session_id: Some(
                "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4"
            )
        }
    }
2019-07-19 13:58:35.353 14826-14883/ai.snips.snipsdemo:snipsProcessingService W/snips_broadcast_chann..: could not send data to audio subscriber, removing it: "SendError(..)"
2019-07-19 13:58:35.409 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_kaldi::logs: Spent 0.046526 seconds in looped compilation.
2019-07-19 13:58:35.409 14826-14874/ai.snips.snipsdemo:snipsProcessingService I/snips_asr_hermes: Idle
2019-07-19 13:58:35.409 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_asr_hermes: ignore stop request, already idle
2019-07-19 13:58:50.710 14826-14880/ai.snips.snipsdemo:snipsProcessingService I/snips_dialogue_lib::c..: Session [b7f7a8eb-407c-483f-9a79-65c7c48f9fb4]: closing session which was active: Timeout
2019-07-19 13:58:50.711 14826-14880/ai.snips.snipsdemo:snipsProcessingService I/snips_dialogue_lib::c..: Site [default]: reset site -> turn off ASR and turn on Hotword
2019-07-19 13:58:50.711 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Dialogue/DialogueSessionEnded {
        status: SessionEndedMessage {
            session_id: "b7f7a8eb-407c-483f-9a79-65c7c48f9fb4",
            custom_data: None,
            termination: Timeout,
            site_id: "default"
        }
    }
2019-07-19 13:58:50.711 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Asr/AsrStopListening {
        site: SiteMessage {
            site_id: "default",
            session_id: None
        }
    }
2019-07-19 13:58:50.711 14826-14881/ai.snips.snipsdemo:snipsProcessingService D/hermes_inprocess: Publishing Hotword/IdentifiableToggleableToggleOn {
        site: SiteMessage {
            site_id: "default",
            session_id: None
        },
        component: Hotword
    }
2019-07-19 13:58:50.713 14826-14874/ai.snips.snipsdemo:snipsProcessingService D/snips_asr_hermes: ignore stop request, already idle
2019-07-19 13:58:50.715 14826-14871/ai.snips.snipsdemo:snipsProcessingService I/snips_hotword_lib::au..: Audio thread for site default started.

The only thing that sounds odd to me is this part. 

ai.snips.snipsdemo:snipsProcessingService W/snips_broadcast_chann..: could not send data to audio subscriber, removing it: "SendError(..)"
fredszaq commented 5 years ago

Ok so for some reason the NLU component is not responding (the log you pointed out has not relation to that)

WOuld be interesting to see the logs during the start of the service, we should have something there indicating why it has stopped

erksch commented 5 years ago

Alright! I think I found the error in the logs on start:

2019-07-19 16:05:37.047 25505-25585/ai.snips.snipsdemo:snipsProcessingService E/snips_nlu_hermes: nlu thread ended with error: Unable to read file '/storage/emulated/0/Android/data/ai.snips.snipsdemo/files/snips/assistant/nlu_engine/nlu_engine.json'
     -> caused by: Expected model version 0.17.0 but found 0.19.0

How can I change the model version? Is it enough to just change it in the configuration file or is there an option for it in the platform console?

erksch commented 5 years ago

Okay after upgrading to 0.63.3 it works fine! I guess the version that is used in the demo project repo I cloned (0.60.5) is not compatible with the newer model versions.

Thanks for your time and support everyone!

fredszaq commented 5 years ago

Yup that's definitively it. Make sure use use the latest android version (0.63.3) and get a fresh assistant by retraining/downloading it on the console. I'm gonna update the version in the demo app