Solved: 8865 - no video - lower bandwidth renegotiated

apartyka · ‎04-26-2021

Hello All,

I have a problem with video not being displayed at branch#1 8865 phone. If I call branch#2 8865 phone - it works fine.

Source phone: 9971. The same region and location. WAN bandwidth at both branches: similar (ca 10 Mbps)

Some data:

CUCM 12.5.1

Location: all unlimited

Intraregion Bit Rate: 6000

Test call: Phone call connected = dark screen at remote phone. After forcing renegotiation (OFF/ON source camera) = picture appears at remote phone, but instantly freezes.

I noticed that failed branch initialy negoiates bw=1000000 but few seconds later lowers it down to bw=220000

(Re-INVITE comes from CUCM). Can this be caused by Jitter too high (see logs below)?

Some video logs (from 9971)

SUCCESS BRANCH:

7723 NOT 17:14:04.899887 ms-PERFORMANCE.cm_rcvCapturePkt sent to DSP [47:17:0][fd=36][packets=1][bytes=21600]
7725 NOT 17:14:05.567111 ms-DSPFW Neg Jit- seq:23000, pktJit:-277, clk:317255760, Total:2
7726 NOT 17:14:06.198323 ms-DSPFW Neg Jit- seq:23132, pktJit:-3, clk:317312640, Total:3
7727 NOT 17:14:07.068358 ms-DSPFW Neg Jit- seq:23312, pktJit:-7, clk:317390940, Total:4
7728 ERR 17:14:08.630467 ms-DSPLINKMGR msgId:0x126, len:28
7729 NOT 17:14:08.653916 ms-PERFORMANCE- RTPPKTMGR.rtpm_rcvPacket from network [45:11][type=video][sock=31][pkts=1001]
7730 NOT 17:14:08.654052 ms-RTPKTMGR stats [45:11][type=video]
7750 NOT 17:14:14.559561 ms-DSPFW DSP VIDEO:320 0 1 25 372 321 321 1240041 1240041
7751 NOT 17:14:14.559719 ms-DSPFW DSP VIDEO:0 0 0 0 0 0 0 0 0 0
7752 NOT 17:14:14.559807 ms-DSPFW DSP VIDEO: dec vcd: i/p wd=640, i/p ht = 480, o/p wd=640, o/p ht = 480

FAILURE BRANCH:

5754 NOT 16:58:42.554846 ms-PERFORMANCE.cm_rcvCapturePkt sent to DSP [40:17:0][fd=36][packets=1][bytes=21600]
5754 NOT 16:58:42.554846 ms-DSPFW Neg Jit- seq:20995, pktJit:-81, clk:234184230, Total:2
5755 NOT 16:58:42.784494 ms-DSPFW Neg Jit- seq:21044, pktJit:-69, clk:234205290, Total:3
5756 NOT 16:58:44.188321 ms-DSPFW Neg Jit- seq:21337, pktJit:-124, clk:234331560, Total:4
5757 NOT 16:58:45.046551 ms-DSPFW DSP VIDEO:98 0 1 24 122 99 99 383884 383884
5758 NOT 16:58:45.046687 ms-DSPFW DSP VIDEO:0 0 0 0 0 0 0 0 0 0
5759 NOT 16:58:45.046774 ms-DSPFW DSP VIDEO: dec vcd: i/p wd=640, i/p ht = 480, o/p wd=640, o/p ht = 480

Some earlier negotiation data

SUCCESS BRANCH:

8538 NOT 17:17:10.951612 ms-RTCP.rtcpm_startRtcp [50:7:9][local IPv4=10.127.184.38, port=25917][remote IPv4=10.127.236.71, port=0]
8539 NOT 17:17:10.951690 ms-RTCP.rtcpm_startRtcp [session=50][socket=28] socket already created.
8540 NOT 17:17:10.951765 ms-ms_updateRtcp [session=50][isVideo=0x00000001][status=0],[rtcp4videoEnable=1],[rtcpEnable=1]
8541 NOT 17:17:10.951845 CVM-SIPCC-MED_API: vcmRtpToMediaPayload: 126: 126: 20
8542 ERR 17:17:10.951920 CVM-SIPCC-PLAT_API: jSessionGetVideoMuteState: call_id=135, line=1
8543 NOT 17:17:10.952004 ms-RTPSESSION.ms_addRTPTxParam video tx remote ip: 10.127.236.71, ipv4(0), port 23024,
security 0, unenc_srtcp 0, dynamicPayloadType 126
profile_level_id 0x428016, packetization_mode 1,
sprop_parameter_set "",
tias_bw 1000000, max_br 0, max_mbps 3600, max_fs 108000
8544 NOT 17:17:10.952095 ms-VIDEO.video_get_profile_attribs [profile_level_id=0x00428016:2.2][bw=1000000:1000000][width=640][height=360][fps=30]
[max_mbps=108000:108000][max_fs=3600:3600][max_br kbps=0:1000]
8545 NOT 17:17:10.952240 ms-RTPSESSION.ms_addRTPTxParam exit [session=49][status=0]
8546 ERR 17:17:10.952319 CVM-SIPCC-PLAT_API: jSessionGetVideoMuteState: call_id=135, line=1
8547 NOT 17:17:10.952406 ms-RTPSESSION.ms_startRTPSessionTx [session=49][mute=0] enter
8548 NOT 17:17:10.952481 ms-RTPSESSION.ms_allocateRTPSessionTx enter [session=49]

FAILURE BRANCH:

5890 NOT 16:58:45.580384 ms-RTCP.rtcpm_startRtcp [39:7:9][local IPv4=10.127.184.38, port=17219][remote IPv4=10.127.230.113, port=0]
5891 NOT 16:58:45.580446 ms-RTCP.rtcpm_startRtcp [session=39][socket=28] socket already created.
5892 NOT 16:58:45.580511 ms-ms_updateRtcp [session=39][isVideo=0x00000001][status=0],[rtcp4videoEnable=1],[rtcpEnable=1]
5893 NOT 16:58:45.580579 ms-RTCP.rtcpm_startRtcp [41:11:13][local IPv4=10.127.184.38, port=18051][remote IPv4=0.0.0.0, port=0]
5894 NOT 16:58:45.580669 ms-RTCP.rtcpm_startRtcp [session=41][socket=32] socket already created.
5895 NOT 16:58:45.580758 ms-ms_updateRtcp [session=41][isVideo=0x00000001][status=0],[rtcp4videoEnable=1],[rtcpEnable=1]
5896 NOT 16:58:45.580846 CVM-SIPCC-MED_API: vcmRtpToMediaPayload: 126: 126: 20
5897 ERR 16:58:45.580931 CVM-SIPCC-PLAT_API: jSessionGetVideoMuteState: call_id=132, line=1
5898 NOT 16:58:45.581027 ms-RTPSESSION.ms_addRTPTxParam video tx remote ip: 10.127.230.113, ipv4(0), port 16768,
security 0, unenc_srtcp 0, dynamicPayloadType 126
profile_level_id 0x428016, packetization_mode 1,
sprop_parameter_set "",
tias_bw 220000, max_br 0, max_mbps 3600, max_fs 108000
5899 NOT 16:58:45.581208 ms-VIDEO.video_get_profile_attribs [profile_level_id=0x00428016:2.2][bw=220000:220000][width=176][height=144][fps=30]
[max_mbps=108000:108000][max_fs=3600:3600][max_br kbps=0:220]
5900 NOT 16:58:45.581323 ms-RTPSESSION.ms_addRTPTxParam exit [session=41][status=0]
5901 ERR 16:58:45.581414 CVM-SIPCC-PLAT_API: jSessionGetVideoMuteState: call_id=132, line=1
5902 NOT 16:58:45.581487 ms-RTPSESSION.ms_startRTPSessionTx [session=41][mute=0] enter
5903 NOT 16:58:45.581547 ms-RTPSESSION.ms_allocateRTPSessionTx enter [session=41]
5904 NOT 16:58:45.581612 ms-VIDEO.video_get_encode_bitrate width = 176, height = 144, fps = 30, bw = 220000
5905 NOT 16:58:45.581675 ms-VIDEO.video_get_encode_bitrate bitrate after correction is 220000
5906 NOT 16:58:45.581736 ms-CALLBKMGR.cb_videoInfo [seh=41][videoSink=1][size=16]
5907 NOT 16:58:45.581797 ms-CALLBKMGR.cb_videoInfo [res=176x144][loc=0x0]
5908 NOT 16:58:45.581860 ms-RTPSESSION.ms_allocateRTPSessionTx exit [session=41][status=0]
5909 ERR 16:58:45.581922 ms-V4L2MGR.v4l2mgr_dequeue_buff VIDIOC_DQBUF Failed - Invalid argument [fd=36]

I hope I did not overload the description.

Thanks for answers in advance.

Adam

apartyka · ‎06-14-2021

Hello All,

Just for the record: we noticed, that MTU for the WAN network (based on GET-VPN) was lower then used by 9971 (99xx series in general). I got info from TAC, that MTU was hardcoded in 9971 so it couldn't be adjusted (negotiated).

Tests proved that when we disabled GET-VPN for video traffic, video from 9971 was received at 8865 at remote site with no problems at all.

Additionally we can assume that 8865s are aware of MTU set for CUCM (it was 1410) and are able to adjust it, because 9971 was receiving 8865's video no matter what MTU (at network level) was available between sites.

But how to deduce it from logs?

Thanks for your time.

Regards

Adam

View solution in original post

VON CLAWSON · ‎04-27-2021

This is an old bug but might point you in the right direction.

https://bst.cloudapps.cisco.com/bugsearch/bug/CSCuz70845/?rfs=iqvred

Also, have you tried adjusting the allowed bandwidth on the phone settings --> Video --> Bandwidth Allowance.

Please rate if this helps.

apartyka · ‎04-29-2021

Von Clawson, thanks for reply and your suggestions.

I tested the problem with the newest available firmware 12.8(1)SR1 - no change. The same firmware version in other location works fine.

I looked for the Video settings you mentioned, but I assumed that option is available in Multiplatform firmware version which is not the case here

Regards

Adam

apartyka · ‎06-14-2021

Hello All,

Just for the record: we noticed, that MTU for the WAN network (based on GET-VPN) was lower then used by 9971 (99xx series in general). I got info from TAC, that MTU was hardcoded in 9971 so it couldn't be adjusted (negotiated).

Tests proved that when we disabled GET-VPN for video traffic, video from 9971 was received at 8865 at remote site with no problems at all.

Additionally we can assume that 8865s are aware of MTU set for CUCM (it was 1410) and are able to adjust it, because 9971 was receiving 8865's video no matter what MTU (at network level) was available between sites.

But how to deduce it from logs?

Thanks for your time.

Regards

Adam

Sergio Quezada · ‎06-18-2021

Hello,
Have you had a look at the Locations configuration for both sites (stare and compare) also you may want to allocate a little more bandwidth for Video. Just a thought

Configure Location Bandwidth Manager and Related Alerts:
https://www.cisco.com/c/en/us/support/docs/unified-communications/unified-communications-manager-callmanager/213794-configure-location-bandwidth-manager-and.html

GOOD:

8544 NOT 17:17:10.952095 ms-VIDEO.video_get_profile_attribs [profile_level_id=0x00428016:2.2][bw=1000000:1000000][width=640][height=360][fps=30]
[max_mbps=108000:108000][max_fs=3600:3600][max_br kbps=0:1000]

BAD:

5899 NOT 16:58:45.581208 ms-VIDEO.video_get_profile_attribs [profile_level_id=0x00428016:2.2][bw=220000:220000][width=176][height=144][fps=30]
[max_mbps=108000:108000][max_fs=3600:3600][max_br kbps=0:220]

Regards,
Sergio Quezada

apartyka · ‎09-30-2021

Hello Sergio,

Thanks for your try but this problem was not related to bandwidth restrictions (I set unlimited for video and immersive).

The problem was caused by lower MTU along the WAN path then 9971 required (and could not adjust).

Regards

Adam