Voicemail pro not handling inbound calls on SIP

[rm81]

Hello All

Currently have an issue on and ip500v2 with voicemail pro

Ip500v2:9.1.700.163 with VCM 32
VMPRO:9.1.7.5

Handsets on site 54 series and D100 dects at a remote site connected via a vpn

The system has multiple ISDN 2 connections and a Gamma Converged SIP connection

Incoming and outgoing calls on the sip trunk are fine both ways

The issue i have is that calls on the gamma SIP trunks routing to voicemail pro are not connecting to the configured AA

I have created a simple VMPRo config that simply transfers the call direct to a spare extension, when monitoring the call on SSA i see no indication of the call connecting only that the state is "seized"

I have attached a copy of a monitor trace i ran whilst trying to connect the call via voicemail pro.

If i use the same call flows on the ISDN DDI's i have no problem so suggesting it possibly could be a codec perhaps.

Strange as i have never encountered this previously on similar set ups

UNICODE-UTF8
eng
8.0.20>
Call-ID: f8eece-6e01a8c0-13c4-6006-1c-0-1c
CSeq: 4 REGISTER
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f878-0-f53848
Max-Forwards: 70
Supported: replaces,100rel,timer
User-Agent: Avaya D100 (D100_1.2.5_0.9.6 00:E0:11:0C:AE:58)
Expires: 180
Authorization: Digest username="609",realm="ipoffice",nonce="e95b467b8d34b8b457c6",uri="sip:192.168.0.20:5060",response="bdb65f78328cbd53bd701cc58aeda976",algorithm=MD5
Contact: <sip:609@192.168.1.110:5060>
Content-Length: 0

13:00:50 8382423mS SIP Reg/Opt Rx: phone
REGISTER sip:192.168.0.20:5060 SIP/2.0
From: <sip:609@192.168.0.20>;tag=f625d0-6e01a8c0-13c4-6006-1c-0-1c
To: <sip:609@192.168.0.20>
Call-ID: f8eece-6e01a8c0-13c4-6006-1c-0-1c
CSeq: 4 REGISTER
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f878-0-f53848
Max-Forwards: 70
Supported: replaces,100rel,timer
User-Agent: Avaya D100 (D100_1.2.5_0.9.6 00:E0:11:0C:AE:58)
Expires: 180
Authorization: Digest username="609",realm="ipoffice",nonce="e95b467b8d34b8b457c6",uri="sip:192.168.0.20:5060",response="bdb65f78328cbd53bd701cc58aeda976",algorithm=MD5
Contact: <sip:609@192.168.1.110:5060>
Content-Length: 0

13:00:50 8382425mS SIP Reg/Opt Tx: phone
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f878-0-f53848
From: <sip:609@192.168.0.20>;tag=f625d0-6e01a8c0-13c4-6006-1c-0-1c
Call-ID: f8eece-6e01a8c0-13c4-6006-1c-0-1c
CSeq: 4 REGISTER
User-Agent: IP Office 9.1.7.0 build 163
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,NOTIFY,INFO,SUBSCRIBE,REGISTER,PUBLISH
Contact: <sip:609@192.168.1.110:5060>
Date: Fri, 22 Jul 2016 12:00:50 GMT
Expires: 180
Supported: timer
Server: IP Office 9.1.7.0 build 163
To: <sip:609@192.168.0.20>;tag=ef6c5a55dbc5d061
Content-Length: 0

13:00:50 8382425mS SIP Tx: UDP 192.168.0.20:5060 -> 192.168.1.110:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f878-0-f53848
From: <sip:609@192.168.0.20>;tag=f625d0-6e01a8c0-13c4-6006-1c-0-1c
Call-ID: f8eece-6e01a8c0-13c4-6006-1c-0-1c
CSeq: 4 REGISTER
User-Agent: IP Office 9.1.7.0 build 163
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,NOTIFY,INFO,SUBSCRIBE,REGISTER,PUBLISH
Contact: <sip:609@192.168.1.110:5060>
Date: Fri, 22 Jul 2016 12:00:50 GMT
Expires: 180
Supported: timer
Server: IP Office 9.1.7.0 build 163
To: <sip:609@192.168.0.20>;tag=ef6c5a55dbc5d061
Content-Length: 0

13:00:50 8382426mS SIP Rx: UDP 192.168.1.110:5060 -> 192.168.0.20:5060
REGISTER sip:192.168.0.20:5060 SIP/2.0
From: <sip:610@192.168.0.20>;tag=f63308-6e01a8c0-13c4-6006-1e-0-1e
To: <sip:610@192.168.0.20>
Call-ID: f8f026-6e01a8c0-13c4-6006-1e-0-1e
CSeq: 4 REGISTER
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f8a1-0-f539a0
Max-Forwards: 70
Supported: replaces,100rel,timer
User-Agent: Avaya D100 (D100_1.2.5_0.9.6 00:E0:11:0C:AE:58)
Expires: 180
Authorization: Digest username="610",realm="ipoffice",nonce="1334a7606a0e30766db9",uri="sip:192.168.0.20:5060",response="2a41ba6115da7b76bb169d51bb55c9b3",algorithm=MD5
Contact: <sip:610@192.168.1.110:5060>
Content-Length: 0

13:00:50 8382428mS SIP Reg/Opt Rx: phone
REGISTER sip:192.168.0.20:5060 SIP/2.0
From: <sip:610@192.168.0.20>;tag=f63308-6e01a8c0-13c4-6006-1e-0-1e
To: <sip:610@192.168.0.20>
Call-ID: f8f026-6e01a8c0-13c4-6006-1e-0-1e
CSeq: 4 REGISTER
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f8a1-0-f539a0
Max-Forwards: 70
Supported: replaces,100rel,timer
User-Agent: Avaya D100 (D100_1.2.5_0.9.6 00:E0:11:0C:AE:58)
Expires: 180
Authorization: Digest username="610",realm="ipoffice",nonce="1334a7606a0e30766db9",uri="sip:192.168.0.20:5060",response="2a41ba6115da7b76bb169d51bb55c9b3",algorithm=MD5
Contact: <sip:610@192.168.1.110:5060>
Content-Length: 0

13:00:50 8382431mS SIP Reg/Opt Tx: phone
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.110:5060;rport;branch=z9hG4bK-187-5f8a1-0-f539a0
From: <sip:610@192.168.0.20>;tag=f63308-6e01a8c0-13c4-6006-1e-0-1e
Call-ID: f8f026-6e01a8c0-13c4-6006-1e-0-1e
CSeq: 4 REGISTER
User-Agent: IP Office 9.1.7.0 build 163
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,NOTIFY,INFO,SUBSCRIBE,REGISTER,PUBLISH
Contact: <sip:610@192.168.1.110:5060>
Date: Fri, 22 Jul 2016 12:00:50 GMT
Expires: 180

kind regards and thanks

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[derfloh]

That trace contains registration of a D100 handset but nothing about any call.

I bet you only have a URI in your SIP trunk with "use internal data" and you don't have the SIP settings configured in Manager under system - voicemail.

Better way is to have another URI containing*/*/* for inbound calls to use ICR to route SIL calls.

 

[rm81]

Hi derfloh

Thanks for the feed back much appreciated.

You are correct i hadn't added in the */*/*

However the call when pointed to a VM: now seems to hit the voicemail and not follow the call flow.

I have compared it with one i set up recently and the SIP element of the voicemail tab was also blank (what would be the required detail for these fields) the only difference being on the set up was that i had added */*/*

So to clarify now when i route the call to a VM: the call goes straight through to the mailbox.

Many thanks for your Help

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[Pepp77]

If you have it pointed at VM:Mailbox and do not have a module called Mailbox, it will go directly to the voicemail mailbox for Mailbox even though it doesnt exist.

| ACSS SME |

 

[rm81]

Thanks Pepp,

Currently i have it pointing to an existing call flow i even copied the module name as the destination for the call route to make sure i wasnt doing something silly and still it will only target the mailbox

Thanks for your reply

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[Ragnorak]

I don't think they ever increased the 15 character limit on VM:ModuleName. So the VM: is three characters and thus the module name is limited to 12 characters. Is your module name over 12 characters?

 

[rm81]

Hi Guys,

THanks for the feed back your time is appreciated.

To rule out the naming of the module a recreated this as test and also encountered the same issue.

Highly strange as i have now mirrored the set up from a previous install. still it will only target the mailbox

Thanks in advance

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[janni78]

Do a default monitor trace.

Also did you put VM:ModuleName directly in ICR or is it through a shortcode?

"Trying is the first step to failure..." - Homer

 

[rm81]

Hi Guys,

Thank you for the replies.

The voicemail module is targeted via the ICR and not via a short code i have ran a monitor trace as below of a call coming in from my mobile targeting the module VM:Open

My next theory is to carry out a reinstall of VMPRO.

TO confirm VMPRO is running on the below server alongside ONEX

CPU: Intel (R) Xeon (R) CPU E3-1226 v3 @ 3.30 GHZ
RAM: 16.0 GB

OS; Windows Server 2012 R2 64bit





Trace results added below

UNICODE-UTF8
eng

********** Warning: Logging to Screen Started **********
10:19:10 344311547mS RES: Tue 26/7/2016 10:19:09 FreeMem=54094748 Heap=52724848(40) Cache=1369900 MemObjs=18306(21499) CMMsg=7(8) ASN=0 Buff=5200 1357 1000 7424 5 Links=63145(63270) BTree=1853(1873) CPU=11.17% CPUStats=04.13%/3/6/935/14707/15063/00.04%/
0/02.58% MCR=0 MCW=0
10:19:10 344311547mS RES2: IP 500 V2 9.1.7.0 build 163 Tasks=53 RTEngine=3 CMRTEngine=0 ExRTEngine=0 Timer=62 Poll=0 Ready=1 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=40(TLS=7) TAPI=1 Partner=40 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
10:19:10 344311547mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
10:19:10 344311547mS RES5: CLog MemObjs=471 FreePoolMem(Objs)=6708(129) TotalMem=134800

********** Warning: Logging to Screen Stopped **********

********** Warning: Logging to Screen Started **********
10:19:33 344335907mS SIP Rx: UDP 10.128.0.185:5060 -> 10.0.19.26:5060
INVITE sip:01332973440@10.0.19.26;user=phone SIP/2.0
Max-Forwards: 69
Session-Expires: 3600;refresher=uac
Min-SE: 600
Supported: timer, 100rel
To: <sip:01332973440@10.128.0.185:5060;user=phone>
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
P-Asserted-Identity: <sip:07766075924@10.128.0.185;user=phone>
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 1 INVITE
Allow: UPDATE,PRACK,INFO,NOTIFY,REGISTER,OPTIONS,BYE,INVITE,ACK,CANCEL
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bK2239c151331d05398559a342900d6388
Contact: <sip:07766075924@10.128.0.185:5060>
Content-Type: application/sdp
Accept: application/sdp
Content-Length: 213

v=0
o=MSX57 3586142243386424657 1 IN IP4 10.128.0.185
s=sip call
c=IN IP4 10.128.0.186
t=0 0
m=audio 21928 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
10:19:33 344335911mS CMCallEvt: 0000000000000000 0.3437.0 -1 BaseEP: NEW CMEndpoint f4edf7b8 TOTAL NOW=1 CALL_LIST=0
10:19:33 344335911mS Stun: Info: Line 17: Not using STUN for media in this case.
10:19:33 344335914mS SIP Tx: UDP 10.0.19.26:5060 -> 10.128.0.185:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bK2239c151331d05398559a342900d6388
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 1 INVITE
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer,100rel
Server: IP Office 9.1.7.0 build 163
To: <sip:01332973440@10.128.0.185:5060;user=phone>;tag=4d610580f45a5853
Content-Length: 0

10:19:33 344335917mS CMCallEvt: CREATE CALL:553 (f190bc40)
10:19:33 344335917mS CMCallEvt: 0000000000000000 0.3438.0 -1 BaseEP: NEW CMEndpoint f4ef4908 TOTAL NOW=2 CALL_LIST=0
10:19:33 344335919mS CMLineRx: v=0
CMSetup
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
Called[502] Type=Default (100) Reason=CMDRdirect SndComp Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ALaw
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=07766075924@10.128.0.185
IE CMIEDeviceDetail (231) c0a8001400000d6d LOCALE=eng HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x0 rx_gain=32 tx_gain=32 ep_callid=3437 ipaddr=192.168.0.20 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=01332973440
10:19:33 344335920mS CD: CALL: 17.3437.1 BState=Idle Cut=1 Music=0.0 Aend="Line 17" (0.0) Bend="" [] (0.0) CalledNum=502 () CallingNum=07766075924@10.128.0.185 () Internal=0 Time=4 AState=Idle
10:19:33 344335920mS CMCallEvt: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: StateChange: END=A CMCSIdle->CMCSDialInitiated
10:19:33 344335920mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: LOOKUP CALL ROUTE: GID=17 type=100 called_party=502 sub= calling=07766075924@10.128.0.185 calling_sub= dir=in complete=1 ses=0
10:19:33 344335920mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: SET BESTMATCH: length 11 vs -1 match=01332973440 dest=VM:Open
10:19:33 344335920mS CMCallEvt: Priority hike: call 553 priority 0->1
10:19:33 344335920mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: LOOKUP ICR: DDI=01332973440 CGPN=07766075924@10.128.0.185 (Destination VM:Open ) => CDPN=VM:Open
10:19:33 344335921mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: ADD TARGET (N): number=VM:Open type=100 depth=1 nobar=1 setorig=1 ses=0
10:19:33 344335921mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: ADD VM TARGET
10:19:33 344335921mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: MakeVoicemailTarget pbx=<null> local=1 type=1
10:19:33 344335921mS CMMap: a=4.1 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder(f564a920) resource busy 1, total 32
10:19:33 344335922mS CMCallEvt: 0000000000000000 0.3439.0 -1 BaseEP: NEW CMEndpoint f1941584 TOTAL NOW=3 CALL_LIST=1
10:19:33 344335922mS CMTARGET: c0a8001400000d6f 0.3439.0 553 RAS.0: ADD PRIMARY
10:19:33 344335922mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: ADD VM TARGET: SUCCEEDED
10:19:33 344335922mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: INITIAL TARGETING SUCCEEDED
10:19:33 344335922mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: GetNoAnswerTimer:20
10:19:33 344335923mS CMCallEvt: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: StateChange: END=A CMCSDialInitiated->CMCSDialled
10:19:33 344335924mS CMLineTx: v=0
CMProceeding
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
10:19:33 344335924mS CMCallEvt: 0000000000000000 0.3438.0 553 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
10:19:33 344335925mS CMCallEvt: c0a8001400000d6f 0.3439.0 553 RAS.0: StateChange: END=T CMCSIdle->CMCSOffering
10:19:33 344335925mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 0->3439 )
10:19:33 344335925mS CMExtnTx: v=RAS, p1=0
CMSetup
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[Open] Type=Voicemail (102) Reason=CMDRX_Attendant SndComp Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ALaw
BChan: slot=21 chan=42
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=07766075924@10.128.0.185
IE CMIEDeviceDetail (231) c0a8001400000d6d LOCALE=eng HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=3437 ipaddr=192.168.0.20 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:100 N:100 R:4) number=01332973440
IE CMIEMohSourceId (247) MOH Source = 1
Display [07766075924>Open]
Timed: 26/07/16 10:19
Locale: eng
10:19:33 344335925mS CMMap: a=21.42 b=1.65534 T
10:19:33 344335927mS CMExtnRx: v=RAS, p1=0
CMConnect
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Open
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=Open
IE CMIEDeviceDetail (231) c0a8001400000d6f LOCALE=eng HW=15 VER=9 class=CMDeviceVoicemail type=0 number=0 channel=42 features=0x0 rx_gain=32 tx_gain=32 ep_callid=3439 ipaddr=192.168.0.20 apps=0 loc=0 em_loc=0 features2=0x0 is_spcall=0
10:19:33 344335927mS CMCallEvt: c0a8001400000d6f 0.3439.0 553 RAS.0: StateChange: END=T CMCSOffering->CMCSConnReq
10:19:33 344335927mS CMCallEvt: 0000000000000000 0.3438.0 553 TargetingEP: RequestEnd c0a8001400000d6f 0.3439.0 553 RAS.0
10:19:33 344335927mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: CancelTimer CMTCNoAnswerTimeout
10:19:33 344335928mS CMExtnEvt: v=1011 State, new=Connected old=Idle,0,0,RAS
10:19:33 344335928mS CMCallEvt: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: StateChange: END=A CMCSDialled->CMCSOGConnReq
10:19:33 344335930mS CMMap: IP::SetCodec pcp[308]b0r0 0 -> f564a920
10:19:33 344335932mS CMLineTx: v=0
CMConnect
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
BChan: slot=21 chan=42
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
ConnectedName.Invoke.CodePageISO8859-1
invokeId 14890
user 'Open' presentation Allowed
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Open
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=Open
IE CMIEDeviceDetail (231) c0a8001400000d6f LOCALE=eng HW=15 VER=9 class=CMDeviceVoicemail type=0 number=0 channel=42 features=0x0 rx_gain=32 tx_gain=32 ep_callid=3439 ipaddr=192.168.0.20 apps=0 loc=0 em_loc=0 features2=0x0 is_spcall=0
IE CMIESecurityData (253) 2 item(s)
CMSecurityElement RX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 5)
}
CMSecurityElement TX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 5)
}
10:19:33 344335935mS SIP Tx: UDP 10.0.19.26:5060 -> 10.128.0.185:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bK2239c151331d05398559a342900d6388
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 1 INVITE
Contact: <sip:01332973440@10.0.19.26:5060;transport=udp>
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,NOTIFY
Supported: timer,100rel
Server: IP Office 9.1.7.0 build 163
Min-SE: 3600
Require: timer
Session-Expires: 3600;refresher=uac
To: <sip:01332973440@10.128.0.185:5060;user=phone>;tag=4d610580f45a5853
Content-Type: application/sdp
Content-Length: 200

v=0
o=UserA 2536267031 3523322060 IN IP4 10.0.19.26
s=Session SDP
c=IN IP4 10.0.19.26
t=0 0
m=audio 49152 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
10:19:33 344335936mS CMCallEvt: 0000000000000000 0.3438.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
10:19:33 344335936mS CMCallEvt: 0000000000000000 0.3438.0 -1 BaseEP: DELETE CMEndpoint f4ef4908 TOTAL NOW=2 CALL_LIST=1
10:19:33 344335939mS H323Evt: SESS 8c SetOperational local 10.0.19.26:0 remote 0.0.0.0:0 to 0
10:19:33 344335939mS H323Evt: SESS 8c SetRemUDP 0 -> 21928, remote IP 0.0.0.0 -> 10.128.0.186
10:19:33 344335939mS H323Evt: SESS 8c SetRfc2833: (1) rx payload 101 tx payload 101
10:19:33 344335939mS H323Evt: SESS 8c SetHnt (rtp keepalives): enabled 1, send_initial_packet 0, send_periodic_packets 3
10:19:33 344335939mS CMMap: PCG::MapBChan pcp[308]b0r1 cp_b 0 other_cp_b 0 type CGTypeSimple
10:19:33 344335940mS CMMap: PCGS CPReserveCodec for the other end (pcp[308]b0r1) true
10:19:33 344335940mS CMMap: PCG::MapBChan pcp[44]b1r0 cp_b f5627ecc other_cp_b f5808fb8 type CGTypeSimple
10:19:33 344335940mS CMMap: a=4.1 b=21.42 M12
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::Bind pcp[308]b0r1 to 4.1
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::ConnectVoice (connect) pcp[308]b0r1 echo_cancellation set to 0
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[308]b0r1 Configure 4.1
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Open got rtpRelay ID: 1
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Configure success
10:19:33 344335940mS CMMap: PlatformConnectionAudioSAP::ConnectVoice local IP addr 10.0.19.26:49152, Remote IP addr 10.128.0.186:21928
10:19:33 344335941mS CMMap: PlatformConnectionAudioSAP::ConnectVoice DSP IP addr 1.1.1.3:32768, telogyHost IP addr 1.1.1.1:10
10:19:33 344335941mS CMMap: PlatformConnectionAudioSAP::ConnectVoice rtpRelay Start success
10:19:33 344335941mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[308]b0r1 ConnectIndication 4.1
10:19:33 344335941mS H323Evt: SESS 8c SetOperational local 10.0.19.26:49152 remote 10.128.0.186:21928 to 1
10:19:33 344335944mS CD: CALL: 17.3437.1 BState=Connected Cut=3 Music=0.0 Aend="Line 17" (0.0) Bend="Open(Open)" [VoiceMail] (21.42) CalledNum=Open () CallingNum=07766075924@10.128.0.185 () Internal=0 Time=28 AState=Connected
10:19:34 344336016mS SIP Rx: UDP 10.128.0.185:5060 -> 10.0.19.26:5060
ACK sip:01332973440@10.0.19.26:5060;user=phone SIP/2.0
Max-Forwards: 69
To: <sip:01332973440@10.128.0.185:5060;user=phone>;tag=4d610580f45a5853
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 1 ACK
Allow: UPDATE,INFO,NOTIFY,REGISTER,OPTIONS,BYE,INVITE,ACK,CANCEL
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bKd98cb4ebaadadb7e9e3138bc67318806
Contact: <sip:07766075924@10.128.0.185:5060>
Content-Length: 0

10:19:34 344336019mS CMLineRx: v=0
CMConnectAck
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
Called[] Type=Default (100) Reason=CMDRdirect Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=07766075924@10.128.0.185
IE CMIEDeviceDetail (231) c0a8001400000d6d LOCALE=eng HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=3437 ipaddr=192.168.0.20 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
10:19:34 344336019mS CMCallEvt: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: StateChange: END=A CMCSOGConnReq->CMCSConnected
10:19:34 344336019mS CMTARGET: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: ~CMTargetHandler f4ef1ca8 ep f4edf7b8
10:19:34 344336020mS CMCallEvt: c0a8001400000d6f 0.3439.0 553 RAS.0: StateChange: END=B CMCSConnReq->CMCSConnected
10:19:34 344336022mS CMExtnTx: v=RAS, p1=0
CMConnectAck
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
BChan: slot=21 chan=42
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=07766075924@10.128.0.185
IE CMIEDeviceDetail (231) c0a8001400000d6d LOCALE=eng HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=3437 ipaddr=192.168.0.20 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
10:19:34 344336024mS CMMap: a=21.42 b=0.0 PCGS CPReserveCodec (pcp[308]b0r1) true
10:19:34 344336024mS CMMap: a=21.42 b=0.0 PCGS CPReserveCodec (pcp[308]b0r1) true
10:19:34 344336024mS CMMap: PCG::MapBChan pcp[308]b0r1 cp_b f5808fb8 other_cp_b f5627ecc type CGTypeSimple
10:19:34 344336024mS CMMap: a=21.42 b=4.1 M12
10:19:34 344336038mS CMExtnRx: v=RAS, p1=0
CMFacility
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
Called[CLAIM] Type=ACD (103) Reason=CMDRdirect
10:19:34 344336039mS CMLineTx: v=0
CMFacility
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
Called[CLAIM] Type=ACD (103) Reason=CMDRdirect
BChan: slot=21 chan=42
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Open
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=Open
IE CMIEDeviceDetail (231) c0a8001400000d6f LOCALE=eng HW=15 VER=9 class=CMDeviceVoicemail type=0 number=0 channel=42 features=0x0 rx_gain=32 tx_gain=32 ep_callid=3439 ipaddr=192.168.0.20 apps=0 loc=0 em_loc=0 features2=0x0 is_spcall=0
10:19:34 344336041mS CMExtnRx: v=RAS, p1=0
CMVoiceMailMsg
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
Called[LeaveMessage] Type=Default (100) Reason=CMDRdirect Calling SubAddress[0]
Tag type=Text flags=0x1 [1.] [0x31 0x00 ]
10:19:34 344336041mS CMLineTx: v=0
CMVoiceMailMsg
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
Called[LeaveMessage] Type=Default (100) Reason=CMDRdirect Calling SubAddress[0]
BChan: slot=21 chan=42
Tag type=Text flags=0x1 [1.] [0x31 0x00 ]
10:19:34 344336042mS CMMap: a=21.42 b=0.0 PCGS CPReserveCodec (pcp[308]b0r1) true
10:19:34 344336042mS CMMap: a=21.42 b=0.0 PCGS CPReserveCodec (pcp[308]b0r1) true
10:19:34 344336042mS CMMap: PCG::MapBChan pcp[308]b0r1 cp_b f5808fb8 other_cp_b f5627ecc type CGTypeSimple
10:19:34 344336042mS CMMap: a=21.42 b=4.1 M12
10:19:34 344336043mS CD: CALL: 17.3437.1 BState=Connected Cut=3 Music=0.0 Aend="Line 17" (0.0) Bend="Open(Open)" [VoiceMail] (21.42) CalledNum=Open () CallingNum=07766075924@10.128.0.185 () Internal=0 Time=127 AState=Connected
10:19:34 344336063mS RES: Tue 26/7/2016 10:19:34 FreeMem=54022336 Heap=52683824(40) Cache=1338512 MemObjs=18704(21499) CMMsg=7(8) ASN=0 Buff=5200 1357 1000 7427 5 Links=63188(63270) BTree=1857(1873) CPU=06.90% CPUStats=10.47%/30/40/935/13680/15063/00.12
%/0/02.69% MCR=0 MCW=0
10:19:34 344336064mS RES2: IP 500 V2 9.1.7.0 build 163 Tasks=54 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=69 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=39(TLS=6) TAPI=1 Partner=40 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
10:19:34 344336064mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
10:19:34 344336064mS RES5: CLog MemObjs=471 FreePoolMem(Objs)=6708(129) TotalMem=134800

********** SysMonitor v9.1.7.0 build 163 [connected to 192.168.0.20 (Surescreen)] **********
10:19:36 344338624mS PRN: Monitor Status IP 500 V2 9.1.7.0 build 163
10:19:36 344338624mS PRN: LAW=A PRI=0, BRI=2, ALOG=4, VCOMP=32, MDM=0, WAN=0, MODU=1 LANM=0 CkSRC=1 VMAIL=1(VER=3 TYP=1) 1-X=1 CALLS=1(TOT=553)
10:19:39 344341066mS RES: Tue 26/7/2016 10:19:39 FreeMem=54068240 Heap=52724864(40) Cache=1343376 MemObjs=18577(21499) CMMsg=7(8) ASN=0 Buff=5200 1357 1000 7419 5 Links=63210(63270) BTree=1857(1873) CPU=05.78% CPUStats=06.87%/2/5/935/14168/15063/00.47%/
0/03.11% MCR=0 MCW=0
10:19:39 344341066mS RES2: IP 500 V2 9.1.7.0 build 163 Tasks=53 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=39(TLS=6) TAPI=1 Partner=40 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
10:19:39 344341066mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
10:19:39 344341066mS RES5: CLog MemObjs=471 FreePoolMem(Objs)=6708(129) TotalMem=134800
10:19:52 344354897mS SIP Rx: UDP 10.128.0.185:5060 -> 10.0.19.26:5060
BYE sip:01332973440@10.0.19.26:5060;user=phone SIP/2.0
Max-Forwards: 69
To: <sip:01332973440@10.128.0.185:5060;user=phone>;tag=4d610580f45a5853
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 2 BYE
Allow: UPDATE,INFO,NOTIFY,REGISTER,OPTIONS,BYE,INVITE,ACK,CANCEL
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bK6089b03a6b872c5899889b231abdad62
Contact: <sip:07766075924@10.128.0.185:5060>
Reason: Q.850;cause=16
Content-Length: 0

10:19:52 344354901mS SIP Tx: UDP 10.0.19.26:5060 -> 10.128.0.185:5060
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.128.0.185:5060;branch=z9hG4bK6089b03a6b872c5899889b231abdad62
From: <sip:07766075924@10.128.0.185>;tag=3678513573-743661
Call-ID: 30426481-3678513573-743654@MSX57.gammatelecom.com
CSeq: 2 BYE
Supported: timer,100rel
Server: IP Office 9.1.7.0 build 163
To: <sip:01332973440@10.128.0.185:5060;user=phone>;tag=4d610580f45a5853
Content-Length: 0

10:19:52 344354902mS CMLineRx: v=0
CMReleaseComp
Line: type=SIPLine 17 Call: lid=17 id=3437 in=1
Called[] Type=Default (100) Reason=CMDRdirect Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:0 N:100 R:4) number=07766075924@10.128.0.185
IE CMIEDeviceDetail (231) c0a8001400000d6d LOCALE=eng HW=15 VER=9 class=CMDeviceSIPTrunk type=0 number=17 channel=1 features=0x20 rx_gain=32 tx_gain=32 ep_callid=3437 ipaddr=192.168.0.20 apps=0 loc=999 em_loc=999 features2=0x0 is_spcall=1
Cause=16, Normal call clearing
10:19:52 344354902mS CMCallEvt: c0a8001400000d6d 17.3437.1 553 SIPTrunk Endpoint: StateChange: END=A CMCSConnected->CMCSCompleted
10:19:52 344354904mS PRN: CDR - TCPSend maxqueuesize=500 framecount=0 operational=1
10:19:52 344354905mS CMLOGGING: CALL:2016/07/2610:19,00:00:18,000,07766075924@10.128.0.185,I,Open,502,,,,0,,"",0,n/a
10:19:52 344354905mS CD: CALL: 17.3437.1 BState=Connected Cut=2 Music=0.0 Aend="Line 17" (0.0) Bend="Open(Open)" [VoiceMail] (21.42) CalledNum=Open () CallingNum=07766075924@10.128.0.185 () Internal=0 Time=18989 AState=Idle
10:19:52 344354905mS CD: CALL: 17.3437.1 Deleted
10:19:52 344354906mS CMCallEvt: c0a8001400000d6d 17.3437.1 -1 SIPTrunk Endpoint: StateChange: END=X CMCSCompleted->CMCSDelete
10:19:52 344354906mS CMExtnEvt: RAS: CALL LOST (CMCauseNormal)
10:19:52 344354907mS CMCallEvt: c0a8001400000d6f 0.3439.0 -1 RAS.0: StateChange: END=X CMCSConnected->CMCSCompleted
10:19:52 344354907mS CMExtnEvt: v=1011 State, new=PortRecoverDelay old=Connected,0,0,RAS
10:19:52 344354907mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[Open] Type=Voicemail (102) Reason=CMDRX_Attendant Calling[07766075924@10.128.0.185] Type=Unknown Plan=Default
BChan: slot=21 chan=42
Cause=16, Normal call clearing
10:19:52 344354907mS CMMap: a=21.42 b=0.0 T0
10:19:52 344354908mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 3439->0 )
10:19:52 344354908mS CMCallEvt: c0a8001400000d6f 0.3439.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
10:19:52 344354909mS CMExtnEvt: v=1011 State, new=Idle old=PortRecoverDelay,0,0,RAS
10:19:52 344354909mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
BChan: slot=21 chan=42
Cause=16, Normal call clearing
10:19:52 344354909mS CMCallEvt: c0a8001400000d6f 0.3439.0 -1 BaseEP: DELETE CMEndpoint f1941584 TOTAL NOW=1 CALL_LIST=0
10:19:52 344354909mS CMCallEvt: END CALL:553 (f190bc40)
10:19:52 344354911mS CMCallEvt: c0a8001400000d6d 17.3437.1 -1 BaseEP: DELETE CMEndpoint f4edf7b8 TOTAL NOW=0 CALL_LIST=0
10:19:52 344354912mS CMMap: PCG::UnmapBChan pcp[44]b1r0 cp_b f5627ecc other_cp_b f5808fb8
10:19:52 344354912mS CMMap: a=4.1 b=21.42 M02
10:19:52 344354912mS CMMap: PlatformConnectionAudioSAP:isconnectRtpFilter rtpRelay ID: 1 Close success
10:19:52 344354913mS H323Evt: SESS 8c SetOperational local 10.0.19.26:49152 remote 10.128.0.186:21928 to 0
10:19:52 344354913mS CMMap: PCG::UnmapBChan pcp[308]b0r1 cp_b 0 other_cp_b 0
10:19:52 344354913mS H323Evt: SESS 8c: RTP(END): 10.0.19.26/49152 10.128.0.186/21928 CODEC=Alaw64K(4) PKTSZ=160 RFC2833=on AGE=18974 SENT=942 RECV=944 RTdelay=0 jitter=0 loss=0 remotejitter=0 remoteloss=0
10:19:52 344354914mS CMMap: a=4.1 b=0.0 Mapper::FreeCodec freed CMRTVocoder(f564a920) resource busy 1, total 32
10:19:53 344355076mS RES: Tue 26/7/2016 10:19:53 FreeMem=54081852 Heap=52692192(40) Cache=1389660 MemObjs=18264(21499) CMMsg=7(8) ASN=0 Buff=5200 1357 1000 7422 5 Links=63138(63270) BTree=1856(1873) CPU=06.98% CPUStats=09.80%/14/20/935/13821/15063/00.46
%/0/03.08% MCR=0 MCW=0
10:19:53 344355076mS RES2: IP 500 V2 9.1.7.0 build 163 Tasks=53 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=67 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=39(TLS=6) TAPI=1 Partner=40 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
10:19:53 344355077mS RES4: XML MemObjs=63 PoolMem=4748404(2) FreePoolMem=4733100(0)
10:19:53 344355077mS RES5: CLog MemObjs=471 FreePoolMem(Objs)=6708(129) TotalMem=134800

********** Warning: Logging to Screen Stopped **********

With kind regards and thanks




"Striving for success without hardwork is like trying to harvest where you havent planted

 

[janni78]

Do you have an SBC since Gamma and you use internal IPs on the SIP trunk?

It seems to connect to VM Pro, but do you hear anything during the call or is it just silent?

"Trying is the first step to failure..." - Homer

 

[rm81]

Hi janni78,

Many thanks for your reply

No we have no SBC as running on Gamma converged.

When the call connects you are simply directed to a mailbox. With the call flow not being followed.

If i point one of the clients ISDN lines to the same call flow this works as you would expect

Kind regards & Thanks in advance

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[amriddle01]

Bend="Open(Open)" [VoiceMail] (21.42) CalledNum=Open

What are you doing in the call flow?

 

[rm81]

Hi amriddle01

Thanks for responding

The call is is simply routing to a 5 option AA with no conditions (Deliberately not added in any time or holiday checking) in place from there simply transferring to selected huntgroups.

Kind regards






"Striving for success without hardwork is like trying to harvest where you havent planted

 

[janni78]

Try using dbgview to trace VM Pro.

"Trying is the first step to failure..." - Homer

 

[rm81]

Hi Guys,

Firstly thanks to all for taking the time to reply.

The issue seems to have been resolved by uninstalling reinstalling and importing the call flows.

Haven't discovered the underlying issue unfortunately and the question remains as to why it worked on the ISDN ddi's

Kind regards

"Striving for success without hardwork is like trying to harvest where you havent planted

 

[amriddle01]

Avaya have really f~@ked up VM Pro recently and 9.1 system firmware is pretty poor to say the least, so you're unlikely to get to the bottom of it I'm afraid

 

[rm81]

I had a horrible feeling that may be the case.

Holding my breath for my next couple of 9.1 installs

"Striving for success without hardwork is like trying to harvest where you havent planted