I have attached a single H245 negotiation between CUCM 9.1 and an H323 gateway
Can somebody explain to me why the CUCM does not send a masterslavedetermination message (with a terminaltype and a statusDeterminationNumber) just like the gateway does ? Instead it's only the gateway that sends it and then CUCM sends a masterslavedeterminationack saying that the gateway is the master. Consequently the gateway sends an MSDack to CUCM declaring CUCM as the slave.
This happens ALL the time. Normally the MSD is random but in this scenario obviously it is not. I have done more than a dozen calls using the same gateway and same PSTN number and the gateway always is elected as master and CUCM as slave
I have taken traces from both CUCM and gateway and I can confirm that the CUCM NEVER sends a masterslavedetermination message but only a masterslavedeterminationack.
I think you're just missing some debug output here. The gateway sends a masterslavedeterminationack in response to something so most likely the gateway didn't print the masterslavedetermination it received in the debugs to the monitor buffer getting overloaded.
Here's what I would try:
Disable console logging and monitor logging
no logging console
no logging monitor
Turn on sequence numbers so we can see if anything is lost:
Set up a large logging buffer
logging buffered 5000000
Then clear the log and run your debugs again. Use "show log" to view the output.
Also CallManager traces would be useful if you can attach those as well.
Yes it sends an ACK but I can assure you there is nothing in the logs showing that a callmanager sends a masterslavedetermination. I thought the same as you and I also checked the cucm traces (set to detailed level) and I still see the same scenario. CUCM doesnt send anything and the gateway sends an masteslavedeterminationack back. It cannot be a coincidence that both sides show the same exact thing.
And it's not the first time I see it.
I have another site where I have different set of CUCM / gateway and I see both sides sending masterslavedetermination messages just fine and in that scenario the master / slave election is indeed random. In the above scenario the gateway is always elected as master.
The ACK has to be in response to something though. I'm not sure if maybe H.245 allows an MSDAck to be sent before MSD to force election or something like that. Never heard of something like that. I still think we're just missing it in the logs. I lose MSDs in H.245 debugs all the time. I'd like to see the CallManager traces if you can post those so I can see what's going on with each individual process when this happens.
I agree with you Brian. That's what I expected to see also but I don't. Hence my question on this forum. I attached the cucm traces in detailed level from CUCM where you see the call from beginning to end. The issue is still the same
Just grep for the following string and you will see all the H245 messages related to this call
H245ASN - TtPid=(100837)
You will see that the masterslavedetermination from cucm to the gateway is missing. As I said the fact that I dont see it either on the gw logs or in the cucm logs indicates that the message is not there :)
If you want more details on the call here they are
Incoming CI: 43250205
Outgoing CI: 43250206
H323 guid: 9304E310DE6211E3BC9DC0203267F2A3
I also get the same when I take a sniffer capture in CUCM
This trace is abbreviated and hence there is no way to know what is what...I cant even find the Ttpid number in the trace...I agree with Brian though, what will the gateway be sending msdACK to? It has to be to something it received..Please send the full cucm trace for the call..It is easier to trace h245 negotiation on cucm that on the gateway..
Sorry guys I have put the wrong file. Here it is attached. You can also see the screenshot of the sniffer capture I have uploaded which shows the same issue
I removed the calling / called number and the phone information from the trace
Edit: I read a bit the H245 standard and I think that the ACK is not necessarily a response to an MSD but merely indicates who is the master and who is the slave.
Master-Slave Determination Acknowledge
This is used to confirm whether the terminal is the master terminal or the slave terminal, as
indicated by decision. When decision is of type master, the terminal receiving this message is the
master terminal and when decision is of type slave, it is the slave terminal
What I don't understand is why cucm instructs immediately the gateway to be master and does not send an MSD message.
Thanks for looking into this
Is this device just added as an H.323 gateway? Any non-standard options enabled on it?
Reason I ask is because of the behavior I'm seeing here.
The initial connect request shows the H.323 gateway has a DTMF preference of 4 which is OOB and RFC2833. There shouldn't be any possibility to set a DTMF preference on an H.323 gateway in CUCM. Usually it will always be 1 for No Preference:
24376366.001 |10:01:13.743 |AppInfo |SIG-MediaManager-(271101)::wait_AuConnectRequest, CI(43250205,43250206), capCount(0,8), mcNodeId(0,0), xferMode(7,4), reConnectType(0), mrid (0, 0) IFCreated(0 0) proIns(0 0), AC(0,0), party1DTMF(4 1 0 1 0) party2DTMF(1 3 0 1 0),reConnFlag=0, connType(3,3), IFHand(0,0),MTP(0,0),MRGL(dbabad1d-4435-a96b-0f75-53d9a58a1578,dbabad1d-4435-a96b-0f75-53d9a58a1578) videoCap(0 0), mmCallType(0),FS(0,0), IpAddrMode(0 0) aPid(2, 189, 116386), bPid(2, 58, 17176045) EOType(0 0) MOHAnnConnType(0 0) honorCodec(0 0)
Since H.323 gateways can't do RFC2833, that is immediately stripped out:
24376366.004 |10:01:13.743 |AppInfo |DET-MediaManager-(271101)::getAllow2833FortheCall, 2833 is not allowed for the call
After the incoming terminalCapabilitySet and incoming masterSlaveDetermination, CUCM detects some sort of problem with the codec list:
24376454.013 |10:01:13.759 |AppInfo |RegionsServer: applyCodecFilterIfNeeded - no codecs remained after filtering so restored original 0 caps
This may be because of that DTMF issue or because of the audio codec preference list you have applied.
To resolve, CUCM has to disconnect the 2 call legs and reconnect them:
24376459.002 |10:01:13.759 |AppInfo |DET-MediaManager-(271101)::handle_AuDisconnectRequest, mrid(0,0) ci(4325020543250206) size(1), dt(0)
24376470.001 |10:01:13.759 |AppInfo |SIG-MediaCoordinator-wait_AuReConnectRequest, reConnectType(0)
On the reconnect, we see both sides have no DTMF preference selected and out of band only for DTMF advertisement:
24376472.001 |10:01:13.759 |AppInfo |SIG-MediaManager-(271102)::wait_AuConnectRequest, CI(43250205,43250206), capCount(6,8), mcNodeId(0,0), xferMode(7,4), reConnectType(0), mrid (0, 0) IFCreated(1 1) proIns(100837 136690), AC(0,0), party1DTMF(1 1 0 1 0) party2DTMF(1 1 0 1 0),reConnFlag=1, connType(3,3), IFHand(0,0),MTP(0,0),MRGL(dbabad1d-4435-a96b-0f75-53d9a58a1578,dbabad1d-4435-a96b-0f75-53d9a58a1578) videoCap(0 0), mmCallType(0),FS(0,0), IpAddrMode(0 0) aPid(2, 189, 116386), bPid(2, 58, 17176045) EOType(0 0) MOHAnnConnType(0 0) honorCodec(0 0)
CUCM then sends out its terminalCapabilitySet and sends the terminalCapabilitySetAck
The MasterSlaveDetermination process is then de-queued:
24376519.000 |10:01:13.765 |SdlSig-Q |MsdseMasterSlaveDetermination |idle |Msdse(2,100,23,100837) |TranslateAndTransport(2,100,21,100837) |2,100,13,18061199.3^10.47.6.35^Port 60796 |
Msdse process gets the MsdseDetermineRequest:
24376521.000 |10:01:13.765 |SdlSig |MsdseDetermineRequest |incomingAwaitingResponse |Msdse(2,100,23,100837) |H245SessionManager(2,100,28,100837) |2,100,13,18061199.4^10.47.6.35^Port 60796 |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0]
This results in an SDLError as Msdse does not know what to do with an incoming MsdseDetermineRequest while in the "incomingAwaitingResponse" state:
24376521.001 |10:01:13.765 |SdlError |MsdseDetermineRequest |incomingAwaitingResponse |Msdse(2,100,23,100837) | | |Error: Description: A transition is not defined for the input signal. Check state machine definition in initStateMachine().
When that happens, CUCM defaults to electing itself as master and thus sends out the masterSlaveDeterminationAck:
24376524.001 |10:01:13.765 |AppInfo |H245ASN - TtPid=(100837) -Outgoing #964924 -value MultimediaSystemControlMessage ::= response : masterSlaveDeterminationAck :
decision master : NULL
The gateway confirms it will act as slave:
24376525.001 |10:01:13.767 |AppInfo |H245ASN - TtPid=(100837) [0xa02cf850 1444 bytes] -Incoming #1078721 -value MultimediaSystemControlMessage ::= response : masterSlaveDeterminationAck :
decision slave : NULL
Since CUCM is master, it then selects the codec and sends the first outgoing openLogicalChannel having selected G.711ulaw for the call:
24376537.003 |10:01:13.767 |AppInfo |H245ASN - TtPid=(100837) -Outgoing #964925 -value MultimediaSystemControlMessage ::= request : openLogicalChannel :
dataType audioData : g711Ulaw64k : 20,
multiplexParameters h2250LogicalChannelParameters :
mediaControlChannel unicastAddress : iPAddress :
So it looks like possibly the initial connection, disconnection, reconnection process is putting the Master Slave Determination into a strange state it doesn't have a rule for which results in CUCM assuming the role of master without sending a masterSlaveDetermination. To resolve the issue, we need to determine the reason for the connect, disconnect, reconnect behavior which is most likely due to either that DTMF preference or the audio codec preference list applied.
Thanks for looking into the traces much appreciated. Good catch this DTMF issue must be relevant indeed. Although I don't really know where is it coming from. The gateway does seem to advertise both DTFM as you see in the cucm traces but that's after the wait_AuConnectRequest message where is shows the DTMF mismatch. So it has to be something in CUCM right ?
Just a small correction. The party receiving the MSD which contains the MASTER, is actually the master so in the above scenario the CUCM is the slave (it received the MSD with slave) and the GW is the master.
The config I have could not have been simpler. I am using one device pool (gw and sccp phone are in the same DP) and one region (Default) so there should not be cap mismatch.
The dialpeer I al hitting is number 10 and it is below
dial-peer voice 10 voip
description *** TO CUCM-Prod Sub ***
voice-class codec 1
voice-class h323 1
session target ipv4:10.47.6.35
As you can see the DTMF is indeed OOB (although not RFC2833). The show voice call status shows I am hitting this one
CallID CID ccVdb Port Slot/DSP:Ch Called # Codec MLPP Dial-peers
0x57FCB 7A2 0x48CC9634 0/3/0:15.2 0/1:2 XXXXXXX g711ulaw 1/10
GW has nothing I can see that could influence that. Attached 3 images of the config
I am really not sure why would cucm elect the GW as a MASTER without an MSD. There must be some part of the config that influences that but I cannot figure out which
I did indeed have those backward on which side was slave/master.
It looks like the standards allow for a device to skip sending a masterSlaveDetermination if a masterSlaveDetermination has already been received. Both still have to send a masterSlaveDeterminationAck though.
" Each terminal generates a random number and sends it in the
Master/Slave Determination message. Which terminal is the master is
determined by comparison of the terminal types and the random
numbers. If both endpoints send Master/Slave Determination, both
endpoints will reach the same conclusion about who is master. If one
endpoint receives Master/Slave Determination before sending its own,
it makes the determination. In any case each terminal sends
Master/Slave Determination Ack indicating its conclusion.
Master/Slave Determination Reject is sent if the random numbers
chosen by the two endpoints are the same; when this message is
received, Master/Slave Determination is sent again with a new random
Looking at some other H.323 traces I have for 9.1, it looks like this is now the case.
As for why it always is selecting the gateway as master, I wonder if the default terminalType change in 9.x. Might need to place an outbound test call in order to determine that.
Excellent explanation and thanks for digging this out. Good to know.