Voicemail not working with Video Phones

[Raphael]

Hi,

I have bought two nice Yealink T49G Visio phones.

Video calls work perfectly but I end up with an issue while calling my voicemail.

When I call the voicemail for the first time, I need to set it up.

Everything's fine until I need to record my greeting message.

After the prompt ask me to talk, I can hear the comfort noise for about 1 sec and it disappears.

Whether I talk or not, when I press on any key to end my recording, the call drops with an "out-of-order" message.

When I disable the video on my phone, then everything's working again.

kazoo.log

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_exe:672 (<0.346.19>) moving to action 'cf_voicemail'

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:1470 (<0.358.19>) opening 41b8b7855fb38d94617fb6c784ff78b8

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:1309 (<0.358.19>) loaded voicemail box 41b8b7855fb38d94617fb6c784ff78b8

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:1324 (<0.358.19>) mailbox limited to 100 voicemail messages (has 0 currently)

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:321 (<0.358.19>) caller is the owner of this mailbox

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:322 (<0.358.19>) overriding action as check (instead of compose)

Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:219 (<0.358.19>) caller is the owner of this mailbox, and requires no pin

Jan 17 23:21:45 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:642 (<0.358.19>) caller chose to change their mailbox configuration

Jan 17 23:21:45 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:849 (<0.358.19>) playing mailbox configuration menu

Jan 17 23:21:52 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:875 (<0.358.19>) caller chose to record their unavailable greeting

Jan 17 23:21:52 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:1054 (<0.358.19>) overwriting unavailable greeting  as eb52eb1b71f7790216dfe690f0132137.mp3

Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:1081 (<0.358.19>) error while attempting to record unavailable recording: channel_hungup

Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_voicemail:166 (<0.358.19>) compose voicemail complete

Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_exe:396 (<0.346.19>) channel no longer active, not continuing

Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]: |0_4199...@xxx.xxx.xxx.xxx|cf_exe:613 (<0.346.19>) callflow execution has been stopped: normal

Freeswitch

2017-01-17 23:24:35.878868 [ERR] switch_ivr_play_say.c:496 Unable to establish inbound video stream

2017-01-17 23:24:35.878868 [NOTICE] mod_dptools.c:3061 Hangup sofia/sipinterface_1/xx...@xxxxxx.com:5060 [CS_EXECUTE] [DESTINATION_OUT_OF_ORDER]

2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797 sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797 sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:609 (sofia/sipinterface_1/xx...@xxxxxx.com:5060) State EXECUTE going to sleep

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/xx...@xxxxxx.com:5060) Running State Change CS_HANGUP

2017-01-17 23:24:35.878868 [DEBUG] switch_ivr.c:666 sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message [AUDIO_SYNC] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:809 (sofia/sipinterface_1/xx...@xxxxxx.com:5060) Callstate Change ACTIVE -> HANGUP

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/xx...@xxxxxx.com:5060) State HANGUP

2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/xx...@xxxxxx.com:5060 hanging up, cause: DESTINATION_OUT_OF_ORDER

2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/sipinterface_1/xx...@xxxxxx.com:5060

Seems like the call is dropped because freeswitch is not able to establish a inbound video stream (which I suppose it's normal..)

Any idea what to do ?

regards,

Raphael

[Luis Azedo]

Hi,

create a gist with the full freeswitch log.

2017-01-17 23:24:35.878868 [NOTICE] mod_dptools.c:3061 Hangup sofia/sipinterface_1/xxxxx@xxxxxx.com:5060 [CS_EXECUTE] [DESTINATION_OUT_OF_ORDER]

2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797 sofia/sipinterface_1/xxxxx@xxxxxx.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797 sofia/sipinterface_1/xxxxx@xxxxxx.com:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:609 (sofia/sipinterface_1/xxxxx@xxxxxx.com:5060) State EXECUTE going to sleep

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:543 (sofia/sipinterface_1/xxxxx@xxxxxx.com:5060) Running State Change CS_HANGUP

2017-01-17 23:24:35.878868 [DEBUG] switch_ivr.c:666 sofia/sipinterface_1/xxxxx@xxxxxx.com:5060 skip receive message [AUDIO_SYNC] (channel is hungup already)

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:809 (sofia/sipinterface_1/xxxxx@xxxxxx.com:5060) Callstate Change ACTIVE -> HANGUP

2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:811 (sofia/sipinterface_1/xxxxx@xxxxxx.com:5060) State HANGUP

2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:438 Channel sofia/sipinterface_1/xxxxx@xxxxxx.com:5060 hanging up, cause: DESTINATION_OUT_OF_ORDER

2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/sipinterface_1/xxxxx@xxxxxx.com:5060

Seems like the call is dropped because freeswitch is not able to establish a inbound video stream (which I suppose it's normal..)

Any idea what to do ?

regards,

Raphael

--
You received this message because you are subscribed to the Google Groups "2600hz-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-users+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Raphael]

Hi Luis,

sorry for the delay, here is the link to the log : https://gist.github.com/anonymous/c1f2e64c6d405e497af13bd7f73b3f52

To unsubscribe from this group and stop receiving emails from it, send an email to 2600hz-users...@googlegroups.com.

[J. Erickson]

This happened to me in my testing as well.

After the ERR message shows up indicating that an inbound video stream could not be established, it will record normally.

I watched the FS logs and as soon as the red message appeared it would start recording. It did not record anything I said before the error message.

I am using a VVX 600. Setting video.enable="0" in it's provisioner settings fixed the problem. The setting prevents the phone from attempting to negotiate video codecs in the SDP. I'm guessing when FS sees the attempted video negotiation it tries to wait for a video stream. If no video codes are specific in the SDP, it will not hang.

If you disable the video feature on your Yealinks, or whatever other method needed to prevent video codec SDP negotiation, the problem should resolve.

[Raphael]

Hi,

I'm glad to hear that this issue is present with other vendors.

Disabling the video is working but not quite nice solution in production :-(

[Raphael]

any idea ?

should I post this topic on the dev group ?

[James Aimonetti]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Could be using OPUS for audio?

Also it looked like FreeSWITCH changed codecs mid-stream:

2017-02-08 21:46:34.315336 [DEBUG] switch_core_media.c:2540 alternate payload received (received 9, expecting 107)
2017-02-08 21:46:34.315336 [WARNING] switch_core_media.c:2551 Changing current codec to G722 (payload type 9).
2017-02-08 21:46:34.335332 [DEBUG] switch_core_media.c:2915 Changing Codec from opus@20ms@48000hz to G722@20ms@8000hz
2017-02-08 21:46:34.375335 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2017-02-08 21:46:34.375335 [DEBUG] mod_opus.c:661 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2017-02-08 21:46:34.375335 [DEBUG] switch_core_media.c:3017 Set Codec sofia/sipinterface_1/luxp...@i-ctg.com:5060 G722/8000 20 ms 160 samples 64000 bits 1 channels
2017-02-08 21:46:34.375335 [DEBUG] switch_core_codec.c:123 sofia/sipinterface_1/luxp...@i-ctg.com:5060 Original read codec replaced with G722:9
2017-02-08 21:46:34.405334 [DEBUG] switch_core_media.c:2540 alternate payload received (received 107, expecting 9)
2017-02-08 21:46:34.405334 [WARNING] switch_core_media.c:2551 Changing current codec to opus (payload type 107).
2017-02-08 21:46:34.405334 [DEBUG] switch_core_media.c:2915 Changing Codec from G722@20ms@16000hz to opus@20ms@48000hz
2017-02-08 21:46:34.445339 [DEBUG] mod_opus.c:559 Opus encoder: set bitrate to local settings [72000bps]
2017-02-08 21:46:34.445339 [DEBUG] mod_opus.c:559 Opus encoder: set bitrate to local settings [72000bps]
2017-02-08 21:46:34.445339 [DEBUG] switch_core_media.c:3017 Set Codec sofia/sipinterface_1/luxp...@i-ctg.com:5060 opus/48000 20 ms 960 samples 0 bits 1 channels
2017-02-08 21:46:34.445339 [DEBUG] switch_core_codec.c:123
sofia/sipinterface_1/luxp...@i-ctg.com:5060 Original read codec
replaced with opus:116

If anything, I would post to the FreeSWITCH ML or IRC (search their
tickets too). It could be something with H264 not getting set up as
well:

2017-02-08 21:46:41.215335 [ERR] switch_ivr_play_say.c:496 Unable to establish inbound video stream


That's where I'd start, anyway.

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_exe:672 (<0.346.19>) moving to action

>>>>>> 'cf_voicemail'
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:1470 (<0.358.19>) opening

>>>>>> 41b8b7855fb38d94617fb6c784ff78b8
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:1309 (<0.358.19>) loaded

>>>>>> voicemail box 41b8b7855fb38d94617fb6c784ff78b8
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:1324 (<0.358.19>) mailbox

>>>>>> limited to 100 voicemail messages (has 0 currently)
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:321 (<0.358.19>) caller is the

>>>>>> owner of this mailbox
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:322 (<0.358.19>) overriding

>>>>>> action as check (instead of compose)
>>>>>> Jan 17 23:21:34 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:219 (<0.358.19>) caller is the

>>>>>> owner of this mailbox, and requires no pin
>>>>>> Jan 17 23:21:45 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:642 (<0.358.19>) caller chose to

>>>>>> change their mailbox configuration
>>>>>> Jan 17 23:21:45 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:849 (<0.358.19>) playing mailbox

>>>>>> configuration menu
>>>>>> Jan 17 23:21:52 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:875 (<0.358.19>) caller chose to

>>>>>> record their unavailable greeting
>>>>>> Jan 17 23:21:52 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:1054 (<0.358.19>) overwriting

>>>>>> unavailable greeting as eb52eb1b71f7790216dfe690f0132137.mp3
>>>>>> Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:1081 (<0.358.19>) error while

>>>>>> attempting to record unavailable recording: channel_hungup
>>>>>> Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_voicemail:166 (<0.358.19>) compose

>>>>>> voicemail complete
>>>>>> Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_exe:396 (<0.346.19>) channel no longer

>>>>>> active, not continuing
>>>>>> Jan 17 23:22:09 pp-kazoo-01 2600hz[9008]:

>>>>>> |0_4199984239@xxx.xxx.xxx.xxx|cf_exe:613 (<0.346.19>) callflow execution

>>>>>> has been stopped: normal
>>>>>>
>>>>>>
>>>>>> Freeswitch
>>>>>>
>>>>>> 2017-01-17 23:24:35.878868 [ERR] switch_ivr_play_say.c:496 Unable to
>>>>>> establish inbound video stream
>>>>>> 2017-01-17 23:24:35.878868 [NOTICE] mod_dptools.c:3061 Hangup

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060 [CS_EXECUTE]

>>>>>> [DESTINATION_OUT_OF_ORDER]
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message

>>>>>> [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_session.c:2797

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message

>>>>>> [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:609

>>>>>> (sofia/sipinterface_1/xx...@xxxxxx.com:5060) State EXECUTE going to

>>>>>> sleep
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:543

>>>>>> (sofia/sipinterface_1/xx...@xxxxxx.com:5060) Running State Change

>>>>>> CS_HANGUP
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_ivr.c:666

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060 skip receive message

>>>>>> [AUDIO_SYNC] (channel is hungup already)
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:809

>>>>>> (sofia/sipinterface_1/xx...@xxxxxx.com:5060) Callstate Change ACTIVE

>>>>>> -> HANGUP
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] switch_core_state_machine.c:811

>>>>>> (sofia/sipinterface_1/xx...@xxxxxx.com:5060) State HANGUP

>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:438 Channel

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060 hanging up, cause:

>>>>>> DESTINATION_OUT_OF_ORDER
>>>>>> 2017-01-17 23:24:35.878868 [DEBUG] mod_sofia.c:491 Sending BYE to

>>>>>> sofia/sipinterface_1/xx...@xxxxxx.com:5060

>>>>>>
>>>>>> Seems like the call is dropped because freeswitch is not able to
>>>>>> establish a inbound video stream (which I suppose it's normal..)
>>>>>> Any idea what to do ?
>>>>>>
>>>>>> regards,
>>>>>>
>>>>>> Raphael
>>>>>>
>>>>>> --
>>>>>> You received this message because you are subscribed to the Google
>>>>>> Groups "2600hz-users" group.
>>>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>>>> an email to 2600hz-users...@googlegroups.com.
>>>>>> For more options, visit https://groups.google.com/d/optout.
>>>>>>
>>>>>
>>>>>

- --
James Aimonetti

Lead Systems Architect
"If Dialyzer don't care, I don't care"
2600HzPDX | http://2600hz.com
sip:ja...@2600hz.com
tel:415.886.7905
irc:mc_ @ freenode
-----BEGIN PGP SIGNATURE-----

iQEzBAEBCAAdFiEEvSh+xZ5hP1H8lVIU1Mpr4k9cJWAFAlil2P8ACgkQ1Mpr4k9c
JWC63AgAljDGJVWzibKvSdqgGLqunfyhOY8yOda/noRchNMbh27NHbYDdsopWjKM
JZUHaqz4zaWNxu0M0o284J/CHu5HSWM8lbNkdDRyW53TAD1MbYWreMEjoJkZx/um
2fVC6kr0S29DWR9Oa7552/brR85QqJ9/ccS1I/+Hf3T47WxrOrJ2XxDoMPtx0jYe
x1Ia44IYVRzfRjvo5WefwMW1u0Ce+Btn3cdBBwRzGhP+YPjaAlnjGO/blsOsLf+A
4vSKTA//FNlEyKKSJx92o1hdc8p5AX4w/q0+7KONPjPxQ2gGcsU4LOUKvi+CjqTq
yDd4bGloEqpiOJpXTuw65UVCIibV6w==
=r/Tn
-----END PGP SIGNATURE-----