Mod_dialogflow does not transfer receive last message before call transfer

[ccastela-fuze]

Hello Dave, everyone,

We are having an issue using mod_dialogflow to manage phone calls. It used to work, but since May 30th the last message we expect from mod_dialogflow is not received and the node app locks waiting to read the final message before the call is transferred. The issue appears to happen when mod_dialogflow is handling of two "actions": read message and transfer call.

Are you aware of any changes to DialogFlow or gRPC implementations that may have caused this?

We are using the following components and respective versions: Freeswitch: v1.10.1 Drachtio: v0.8.2 Freeswitch modules: git hash 25a23cf33b9d263e2d3b3acdfb50f56c0d87d38 Best match with freeswitch v1.10.1 NodeJS: v12.19.0 DialogFlow ES

Is this something that has been addressed in newer versions of the components?

If further details are needed, please let me know.

Thank you in advance.

[davehorton]

please get a freeswitch log with loglevel at debug

[goncalocosta1]

Hey @davehorton .

Please find below the freeswitch logs I think are relevant. I can send some more logs if required.

Thank you

0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:55.214205 [INFO] parser.cpp:33 GStrGRPCParser - adding query result 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:55.214205 [INFO] parser.cpp:45 GStrGRPCParser - adding audio config 2022-07-12 10:54:55.214205 [INFO] mod_dialogflow.c:26 json payload for type dialogflow::intent: {"response_id":"5cbc3a4e-cabf-4a8e-908d-1f713a664d0e-aebbc26f","query_result":{"query_text":"transfer to an operator","language_code":"en","speech_recognition_confidence":0,"action":"{\"fulfillment_service\":\"transfer_to_agent\",\"stats\":[\"common:contact_agent:transfer_to_agent\"]}","parameters":{},"all_required_params_present":true,"fulfillment_text":"Ok, transferring your call now.","fulfillment_messages":[{"platform":"TELEPHONY","telephony_transfer_call":{"phone_number":"+XXXXXXXXX"}}],"webhook_source":"webhook","webhook_payload":{"google":{"expectUserResponse":true}},"output_contexts":[{"name":"projects/va-qa-agent-3jxy/agent/sessions/0afef238-01d1-11ed-9510-b5390dedac25/contexts/get_directory_name","lifespan_count":4}],"intent":{"name":"projects/va-qa-agent-3jxy/agent/intents/ff75d653-f2a5-4bec-b81f-fd37c3f7e689","display_name":"0.4. - Contact Agent","webhook_state":"WEBHOOK_STATE_UNSPECIFIED","priority":0,"is_fallback":false,"ml_disabled":false,"end_interaction":false,"input_context_names":[],"events":[],"training_phrases":[],"action":"","output_contexts":[],"reset_contexts":false,"parameters":[],"messages":[],"default_response_platforms":[],"root_followup_intent_name":"","followup_intent_info":[]},"intent_detection_confidence":0.775152,"diagnostic_info":{"webhook_latency_ms":229},"sentiment_analysis_result":{"query_text_sentiment":{"score":0,"magnitude":0}},"knowledge_answers":{"answers":[]}},"alternative_query_results":[],"webhook_status":{"code":0,"message":"Webhook execution successful"},"output_audio_config":{"audio_encoding":"OUTPUT_AUDIO_ENCODING_LINEAR_16","sample_rate_hertz":0,"synthesize_speech_config":{"speaking_rate":1,"pitch":0,"volume_gain_db":0,"effects_profile_id":[],"voice":{"name":"","ssml_gender":"SSML_VOICE_GENDER_UNSPECIFIED"}}}}. 2022-07-12 10:54:55.214205 [DEBUG] google_glue.cpp:317 dialogflow read loop is done 2022-07-12 10:54:55.214205 [DEBUG] google_glue.cpp:193 GStreamer::finish 0x7f30240ab510 2022-07-12 10:54:55.214205 [DEBUG] google_glue.cpp:337 dialogflow read thread exiting 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.234206 [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@18.135.157.83:5060 Command Execute [depth=1] playback(/app/1618.wav) 0afef238-01d1-11ed-9510-b5390dedac25 EXECUTE [depth=1] sofia/drachtio_mrf/nobody@18.135.157.83:5060 playback(/app/1618.wav) 2022-07-12 10:54:56.234206 [DEBUG] switch_core_file.c:391 File /app/1618.wav sample rate 48000 doesn't match requested rate 8000 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.234206 [DEBUG] switch_ivr_play_say.c:1492 Codec Activated L16@8000hz 1 channels 20ms 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_ivr.c:632 sofia/drachtio_mrf/nobody@18.135.157.83:5060 Command Execute [depth=2] hangup() 0afef238-01d1-11ed-9510-b5390dedac25 EXECUTE [depth=2] sofia/drachtio_mrf/nobody@18.135.157.83:5060 hangup() 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [NOTICE] mod_dptools.c:1380 Hangup sofia/drachtio_mrf/nobody@18.135.157.83:5060 [CS_EXECUTE] [NORMAL_CLEARING] 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:51 google_dialogflow_session_cleanup: removed audio file /tmp/0afef238-01d1-11ed-9510-b5390dedac25_126.wav 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_session.c:2905 sofia/drachtio_mrf/nobody@18.135.157.83:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_ivr_play_say.c:1933 done playing file /app/1618.wav 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_session.c:2905 sofia/drachtio_mrf/nobody@18.135.157.83:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_ivr.c:679 sofia/drachtio_mrf/nobody@18.135.157.83:5060 skip receive message [AUDIO_SYNC] (channel is hungup already) 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_session.c:2905 sofia/drachtio_mrf/nobody@18.135.157.83:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_state_machine.c:651 (sofia/drachtio_mrf/nobody@18.135.157.83:5060) State EXECUTE going to sleep 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_state_machine.c:585 (sofia/drachtio_mrf/nobody@18.135.157.83:5060) Running State Change CS_HANGUP (Cur 2 Tot 69) 2022-07-12 10:54:56.954206 [INFO] mod_dialogflow.c:57 Got SWITCH_ABC_TYPE_CLOSE. 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:432 google_dialogflow_session_cleanup: acquiring lock 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:434 google_dialogflow_session_cleanup: acquired lock 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:437 google_dialogflow_session_cleanup: sending writesDone.. 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:193 GStreamer::finish 0x7f30240ab510 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [INFO] google_glue.cpp:443 google_dialogflow_session_cleanup: waiting for read thread to complete 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [INFO] google_glue.cpp:446 google_dialogflow_session_cleanup: read thread completed 2022-07-12 10:54:56.954206 [DEBUG] google_glue.cpp:115 GStreamer::~GStreamer wrote 426 packets 0x7f30240ab510 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [INFO] google_glue.cpp:454 google_dialogflow_session_cleanup: Closed google session 2022-07-12 10:54:56.954206 [DEBUG] mod_dialogflow.c:60 Finished SWITCH_ABC_TYPE_CLOSE. 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_media_bug.c:1289 Removing BUG from sofia/drachtio_mrf/nobody@18.135.157.83:5060 0afef238-01d1-11ed-9510-b5390dedac25 2022-07-12 10:54:56.954206 [DEBUG] switch_core_state_machine.c:848 (sofia/drachtio_mrf/nobody@18.135.157.83:5060) Callstate Change ACTIVE -> HANGUP