Hi to all.
We have problem with occasional missing RTP stream from phone to recorder. This happens only when recording phone is not in same CUCM Group with remote phone (that is not recorded), eg. not registered on same subscriber.
Our setup is as follows:
- 1 publisher + 1 subscriber on one locatian
- 3 subscribers on 3 different locations
- CUCM version 7.1.5.34094-1 (special release with some other bugfixes)
- 4 CUCM Groups for registering phones
- 4 CUCM Groups for some other purposes
- more than 150 regions and device pools
We have done some intensive testing in our LAB environment with this setup:
- 1 publisher + 2 subscribers in same location
- 3 regions, 3 device pools
- PhoneA that is recorded in device pool A, using CUCM group A (subscriber 1)
- PhoneB that is not recorded in device pool B, using different CUCM groups
- SIP Trunk to recorder in device pool A, using CUCM group A
We came with following conclusions:
1. when PhoneB is in CUCM group that uses primary same CUCM for registering (subscriber 1), calls are ALWAYS recorded
2. when PhoneB is in CUCM group that uses primary different CUCM for registering (publisher or subscriber2), calls are SOMETIMES not recorded (in 10 calls including same setup there may be 2 or 3 calls not recorded)
We thougth that there may be some problem with recorder device, transcoding/codec problem...but with intensive testing with different regions, device pools, codecs, with or without transcoders, we allways get same pattern that I described above.
We also monitored network traffic, logs on phones, CUCM and recorder so conclusion is that when recording fails, CUCM actually sends SIP BY message to recorder with "reason protocol: Q.850, reason cause: 47, reason text: null" in SIP message.
This SIP BY message is sent just few miliseconds after accepting SIP connection.
This is a hardest kind of problem, because there is no specific case when ALL calls are not recorded....just SOME calls are not recorded using same setup (case number 2 from above) so it is very difficult to isolate problem.
And here is a log from phone:
6130: NOT 15:52:35.437424 DSP: TRSTREAM, isrEgressReqDiscardpreStreaming 0
6131: NOT 15:52:35.452400 DSP: STREAM- OpenIngressChan- ChanType 1, Remote (host afa6535, port 491a), medType 12, Period 20, VAD 0, TOS b8, stream (37220752, 37220756) --> chan 1
6132: NOT 15:52:35.453135 DSP: STREAM- OpenIngressChan- mix (2, 1), dtmfpayloadtype 0
6133: WRN 15:52:35.454009 DSP: bad ARP Add, -126
6134: NOT 15:52:35.468685 DSP: STREAM- OpenIngressChan- ChanType 1, Remote (host afa6535, port 491c), medType 12, Period 20, VAD 0, TOS b8, stream (37220752, 37220759) --> chan 2
6135: NOT 15:52:35.469383 DSP: STREAM- OpenIngressChan- mix (2, 2), dtmfpayloadtype 0
6136: ERR 15:52:35.470181 DSP: MTTHREAD-bind error*** 125:Address already in use at host afae6dd port 5ba6
6137: ERR 15:52:35.470911 DSP: MT: MTHANDLER- retv -1, errno 125, len 24
6138: NOT 15:52:35.482423 DSP: STREAM- CloseIngressChan- ChanType 1, stream (37220752, 37220759) --> Chan -1
6139: NOT 15:52:35.488971 DSP: STREAM- CloseIngressChan- ChanType 1, stream (37220752, 37220756) --> Chan 1
6140: NOT 15:52:35.489612 DSP: Channel 1 ----
6141: NOT 15:52:35.490136 DSP: Egress frame- buffer x0, audio requests: 0
6142: NOT 15:52:35.490696 DSP: Ingress RTP packets sent- packet count 0
6143: NOT 15:52:35.491213 DSP: Ingress frame- buffer x0, frame count 0, empty attempt 0
6144: NOT 15:52:35.491733 DSP: Ingress frame dump - host interface...
6145: NOT 15:52:35.492212 DSP: 0, 0, 0, 22098c
6146: NOT 15:52:35.492743 DSP: 0, 0, 0
6147: NOT 15:52:35.493323 DSP: *** Unable to GetIngressLateCount, DSP Invalid channel, or invalid frame control, possibly 0
6148: NOT 15:52:35.591012 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - --->ConfigManager PropertyChanged: device.callagent.callcount
6149: NOT 15:52:35.592475 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - <---ConfigManager PropertyChanged: device.callagent.callcount
6150: NOT 15:52:35.645963 DSP: STREAM- OpenIngressChan- ChanType 1, Remote (host afae6f3, port 5eb0), medType 12, Period 20, VAD 0, TOS b8, stream (37220752, 37220752) --> chan 0
6151: NOT 15:52:35.646660 DSP: STREAM- OpenIngressChan- mix (1, 3), dtmfpayloadtype 0
6152: NOT 15:52:35.648035 DSP: Subtracted for CODEC[2] G.729 or G.729B direction:1 cost:25 old budget:84
6153: NOT 15:52:41.603493 DSP: STREAM- CloseEgressChan- ChanType 1, stream (37220752, 37220752) --> Chan 0
6154: NOT 15:52:41.606278 DSP: Added back for CODEC[2] G.729 or G.729B direction:0 cost:16 old budget:59
6155: NOT 15:52:41.607533 DSP: ETHSTAT- (unicast, broadcast, multicast) rx = 99367, 13696, 3107; tx = 240931, 592
6156: NOT 15:52:41.608198 DSP: MIB2- ipInDelivers= 100672, udpInDG= 86433, udpOutDG= 230256, udpNoPort= 2691, udpInErr= 0, icmpInDestUnreach = 462, icmpOutDestUnreach = 255
6157: NOT 15:52:41.615960 DSP: STREAM- CloseIngressChan- ChanType 1, stream (37220752, 37220752) --> Chan 0
6158: NOT 15:52:41.620862 DSP: Added back for CODEC[2] G.729 or G.729B direction:1 cost:25 old budget:75
6159: WRN 15:52:41.865494 JVM: Startup Module Loader|cip.mmgr.dt:? - [MediaMgrSM]: Unhandled Event, State = StateHandsetOffHook Event = EventSetSpeakerModeOff
6160: NOT 15:52:41.870479 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - --->ConfigManager PropertyChanged: device.callagent.callcount
6161: NOT 15:52:41.871923 JVM: Startup Module Loader|cip.cfg.ConfigManager:? - <---ConfigManager PropertyChanged: device.callagent.callcount
This looks like some bug in CUCM 7.1.5; does anyone have same problem or some info about this problem?
Best regards,
SH.
