EventDNOutOfService in case of register request

[corn]

following situation:
we use a T-Server for Avaya Communication Manager Version 7.2.008.01

if our application starts and connects via T-Server to an Avaya Definity switch
our application then requests registering of voice position ids, e.g. voice position
id 3500;
our application sends a registerAddress request and gets an EventRegistered for
id 3500 and at once after this an EventDNOutOfService.
(it's the same for all other voice position ids.)

Question is, why we get this EventDNOutOfService.
Can anybody help me ?


17:06:51.094 Trc 04541 RequestRegisterAddress received from 488 (0002 Fozzie MOS Genesys 5.00)
message RequestRegisterAddress
AttributeThisDN '3500'
AttributeRegisterMode 0
AttributeControlMode 0
AttributeAddressType 0 (Unknown)
AttributeReferenceID 1
map <dn,conf>: find (3500): Ok
[ 4 - ] DN: '3500' Links assigned
(tservice_proc) AddressType set to 1 for 3500
(tservice_proc) ControlMode set to 1 for 3500
** ts7.2.008.01[4] <> ** 17:06:51.0940
08 00 00 1B 08 02 00 23 64 96 1C 13 91 A1 10 02 01 03 02 01 C4 40 08 96 49 05 83 33 35 30 B0
=== parsed message ===
prot_discr = 8
CRV = 23
MsgType = 100 (REGISTER)

Facility:  serv_discr = 17(q932_suppl)  fac_ie = component_tag = A1(INVOKE)
invoke_id tag: 02, value = 3
operation tag: 02, value = 196(Domain_Control)
params = q931_tag = 40
list =
Domain:  type = 3(Extension)  address = [4] 33 35 30 30 '3500'

17:06:51.094 Trc 04541 RequestRegisterAddress received from 488 (0002 Fozzie MOS Genesys 5.00)
message RequestRegisterAddress
AttributeThisDN '3500'
AttributeRegisterMode 0
AttributeControlMode 0
AttributeAddressType 0 (Unknown)
AttributeReferenceID 1
map <dn,conf>: find (3500): Ok
[ 4 - ] DN: '3500' Links assigned
(tservice_proc) AddressType set to 1 for 3500
(tservice_proc) ControlMode set to 1 for 3500
** ts7.2.008.01[4] <> ** 17:06:51.0940
08 00 00 1B 08 02 00 23 64 96 1C 13 91 A1 10 02 01 03 02 01 C4 40 08 96 49 05 83 33 35 30 B0
=== parsed message ===
prot_discr = 8
CRV = 23
MsgType = 100 (REGISTER)

Facility:  serv_discr = 17(q932_suppl)  fac_ie = component_tag = A1(INVOKE)
invoke_id tag: 02, value = 3
operation tag: 02, value = 196(Domain_Control)
params = q931_tag = 40
list =
Domain:  type = 3(Extension)  address = [4] 33 35 30 30 '3500'

17:06:51.0940 [0] 7.2.008.01 send_to_client: message EventRegistered
AttributeEventSequenceNumber 0000000000000003
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 94000
AttributeTimeinSecs 1160492811 (17:06:51)
AttributeAddressType 1 (DN)
AttributeExtensions [37] 00 02 01 00..
'AgentStatus' 0
'status' 128
AttributeReferenceID 1
AttributeThisDN '3500'
17:06:51.094 Trc 04542 EventRegistered sent to 488 (0002 Fozzie MOS Genesys 5.00)
@17:06:51.0940 [0] 7.2.008.01 distribute_event: message EventDNOutOfService
AttributeEventSequenceNumber 0000000000000004
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 94000
AttributeTimeinSecs 1160492811 (17:06:51)
AttributeExtensions [17] 00 01 01 00..
'status' 128
AttributeThisDN '3500'
@17:06:51.0940 [ISCC] Debug: Translate: '' -> ''; result 1 ()
17:06:51.094 Trc 04542 EventDNOutOfService sent to 488 (0002 Fozzie MOS Genesys 5.00)

[LeszekM]

This can happen when a CTI link is down or not working properly.
It seems that messages are only sent to the switch and there's no response. DNs are registered only by the TServer (so you are getting EventRegistered), not by the switch.

Regards,
Leszek

[corn]

Thanks for your quick response.

the T-Server trace shows that the first two "link connect attempts" fail
but the third attempt works and then link connection is ok.

At the moment we don't see why the first two "link connect attempts" fail.
Any idea ?

(link_start) link [4] 'link-tcp' start
(tcp_start) connecting to definity:5678... contacted on socket [516]
map <dn,conf>: find (T-Server_G3si_3:: None
[ 4 - ] DN: 'T-Server_G3si_3::' Links assigned
map <dn,conf>: find (G3si:: None
[ 4 - ] DN: 'G3si::' Links assigned
13:31:31.815 Std 05061 Initialization completed
LCA_set_AppLiveStatus(APP_STATUS_SERVICE_UNAVAILABLE)
@13:31:31.8150 [TCONF] Debug: Application type [ConfigurationServer] is skipped for the Remote Server
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
************************************
LCALayer: REventRegistered on LCA...
************************************
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
13:31:31.815 Trc 04541 Registered received from 416 (CfgServer)
AgentLogin array <+>
  [103] login-id = '42200' <+>
@13:31:31.8310 [TCONF] Debug: Main Switch's Agent Logins are read.Number: 1
@13:31:31.8310 [TCONF] Debug: Configuration is fully initialized
(tcp_connect_handler) definity:5678 is connected on socket [516]
** ts7.2.008.01[4] <> ** 10/11/06 13:31:31.8310
04 1B
13:31:31.831 Trc 31000 Connection Request: Link[4], link number[4], protocol(27)
Status value (0):
  New status: (1) ConnectionInProgress1 - ConnReq sent
  Old status: (0) LinkDown - no TCP/IP connection
(link_stop) link [4] 'link-tcp' stop
(tcp_stop) closed on [516]
-- link[4] @13:31:31.9400 -- TCP/IP connection closed --
13:31:31.940 Std 31011 Disconnected: Link[4], reason [TCP/IP connection closed]
Status value (0):
  New status: (0) LinkDown - no TCP/IP connection
  Old status: (1) ConnectionInProgress1 - ConnReq sent
-- Number of active links: 0 out of 32 --
-- Number of active links: 1 out of 32 --
(link_start) link [4] 'link-tcp' start
(tcp_start) connecting to definity:5678... contacted on socket [520]
(tcp_connect_handler) definity:5678 is connected on socket [520]
** ts7.2.008.01[4] <> ** 13:31:36.9710
04 1A
13:31:36.971 Trc 31000 Connection Request: Link[4], link number[4], protocol(26)
Status value (0):
  New status: (1) ConnectionInProgress1 - ConnReq sent
  Old status: (0) LinkDown - no TCP/IP connection
(link_stop) link [4] 'link-tcp' stop
(tcp_stop) closed on [520]
-- link[4] @13:31:37.0810 -- TCP/IP connection closed --
13:31:37.081 Std 31011 Disconnected: Link[4], reason [TCP/IP connection closed]
Status value (0):
  New status: (0) LinkDown - no TCP/IP connection
  Old status: (1) ConnectionInProgress1 - ConnReq sent
-- Number of active links: 0 out of 32 --
-- Number of active links: 1 out of 32 --
(link_start) link [4] 'link-tcp' start
(tcp_start) connecting to definity:5678... contacted on socket [520]
(tcp_connect_handler) definity:5678 is connected on socket [520]
** ts7.2.008.01[4] <> ** 13:31:42.1280
04 01
13:31:42.128 Trc 31000 Connection Request: Link[4], link number[4], protocol(1)
Status value (0):
  New status: (1) ConnectionInProgress1 - ConnReq sent
  Old status: (0) LinkDown - no TCP/IP connection
13:31:42.393 Trc 31002 Connection Progress: Link[4], progress [Success], reason [Connected]
** link[4] <> ** 13:31:42.3930
13:31:42.393 Trc 31001 Connection Accepted: Link[4], status [Up], reason [N/A]
** ts7.2.008.01[4] <> ** 13:31:42.3930
08 00 00 12 08 02 00 00 46 79 01 87 96 1B 01 81 1B 01 82 1B 01 83
=== parsed message ===
prot_discr = 8
CRV = 0
MsgType = 70 (RESTART)

Restart_Indicator:  restart_class = 7(all_interfaces)
Version: # elems = 3
  value = 1(asai_version_1)  id = [0]
  value = 2(asai_version_2)  id = [0]
  value = 3(asai_version_3)  id = [0]
Status value (0):
  New status: (3) ConnectionInProgress3 - Restart sent
  Old status: (1) ConnectionInProgress1 - ConnReq sent
** link[4] <> ** 13:31:42.3930
08 02 00 00 46 79 01 87 96 1B 01 83 1B 01 82 1B 01 81
=== parsed message ===
prot_discr = 8
CRV = 0
MsgType = 70 (RESTART)

Restart_Indicator:  restart_class = 7(all_interfaces)
Version: # elems = 3
  value = 3(asai_version_3)  id = [0]
  value = 2(asai_version_2)  id = [0]
  value = 1(asai_version_1)  id = [0]
** ts7.2.008.01[4] <> ** 13:31:42.3930
08 00 00 0C 08 02 80 00 4E 79 01 87 96 1B 01 83
=== parsed message ===
prot_discr = 8
CRV = 8000
MsgType = 78 (RESTART ACKNOWLEDGE)

Restart_Indicator:  restart_class = 7(all_interfaces)
Version:  value = 3(asai_version_3)  id = [0]
Status value (0):
  New status: (4) ConnectionInProgress4 - RestartACK sent
  Old status: (3) ConnectionInProgress3 - Restart sent
** link[4] <> ** 13:31:42.4710
08 02 80 00 4E 79 01 87 96 1B 01 83
=== parsed message ===
prot_discr = 8
CRV = 8000
MsgType = 78 (RESTART ACKNOWLEDGE)

Restart_Indicator:  restart_class = 7(all_interfaces)
Version:  value = 3(asai_version_3)  id = [0]
Status value (1):
  New status: (5) LinkUp, auto_register done
  Old status: (4) ConnectionInProgress4 - RestartACK sent
13:31:42.471 Trc 31004 Link[4] Up
-- link[4] @13:31:42.4710 -- Mode changed from None to Primary --
13:31:42.471 Trc 31003 Link Mode Changed: Link[4], new mode [Primary], old mode [None]
** ts7.2.008.01[4] <> ** 13:31:42.4710
08 02 00 00 00 F7 96 7A 07 03 80 90 82 D3 01 03
=== parsed message ===
prot_discr = 8
CRV = 0
MsgType = 247 (MANAGEMENT INFO)

Management:  prot_discr = 3  trans_ref = 0  type = 16(confirmed_oper)  op_value = 2(alarm_status)  param_id = 83(alarm_status_p)  param_len = 1  serv_state = 3(resume)

* FC[4]: Adjusting message flow to 25 messages per 500 ms...

* FC[4]: Adjusting message flow to 50 messages per 500 ms...
@13:31:42.4710 [0] 7.2.008.01 send_to_all: message EventLinkConnected
AttributeEventSequenceNumber 0000000000000001
AttributeCustomerID 'Resources'
AttributeServerStartTime 452cd61e00072fd8 (13:31:42.471000)
AttributeTimeinuSecs 471000
AttributeTimeinSecs 1160566302 (13:31:42)
13:31:42.471 Std 20001 CTI Link connected
LCA_set_AppLiveStatus(APP_STATUS_RUNNING)

[LeszekM]

OK.
Have you got all the DNs configured in CME? Genesys claims it is possible to register DNs dynamically but it's better to have it configured...

Have you got any EventDNBackInService (this appears to be the first event on the DN when the TServer begins to monitor this DN)? If not - it's a link problem.

Then make a test call. Have you got any "call" events (like EventDialing, EventRinging, EventEstablished etc.) in the TServer log?  If not - this is again the link problem.

Regards,
Leszek

[Haldane]

Looks like your getting timeout issue between the Tserver and the Link. Get you network guys to trace between both points to ensure your not getting any lost packets.

[corn]

Thanks for your answers.

Yes, we've configured all DNs.
Yes, we get an EventDnBackInService and call events.

[Fra]

If a client registers a DN during the period of
startup registration and before EventLinkConnected, the DN may become unusable. There's an Engineering Request about this issue. Try to set the "delay-event-link-connected" option to false.

[LeszekM]

Please try changing the AddressType in your registration request from AddressTypeUnknown to AddressTypeDN.

Leszek

[corn]

Thanks again for your answer and suggestions.

- Flag delay-event-link-connected was already false
- We tried AddressTypeDN instead of AddressTypeUnknown but the same result so we're still in the dark ...

14:03:51.647 Trc 04541 RequestRegisterAddress received from 488 (0002 Fozzie MOS Genesys 5.00)
message RequestRegisterAddress
AttributeThisDN '3500'
AttributeRegisterMode 0
AttributeControlMode 0
AttributeAddressType 1 (DN)
AttributeReferenceID 1
map <dn,conf>: find (3500): Ok
[ 4 - ] DN: '3500' Links assigned
...
...
...
14:03:51.6470 [0] 7.2.008.01 send_to_client: message EventRegistered
AttributeEventSequenceNumber 0000000000000003
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 647000
AttributeTimeinSecs 1160654631 (14:03:51)
AttributeAddressType 1 (DN)
AttributeExtensions [37] 00 02 01 00..
'AgentStatus' 0
'status' 128
AttributeReferenceID 1
AttributeThisDN '3500'
14:03:51.647 Trc 04542 EventRegistered sent to 488 (0002 Fozzie MOS Genesys 5.00)
@14:03:51.6470 [0] 7.2.008.01 distribute_event: message EventDNOutOfService
AttributeEventSequenceNumber 0000000000000004
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 647000
AttributeTimeinSecs 1160654631 (14:03:51)
AttributeExtensions [17] 00 01 01 00..
'status' 128
AttributeThisDN '3500'
@14:03:51.6470 [ISCC] Debug: Translate: '' -> ''; result 1 ()

[Fra]

Could you please post also the relative parsed ASAI messages (those mapped by TServer into EventRegistered and EventDnOutOfService)?

[Haldane]

I've seen something simular on meridian switch before where Tserver attemps to register for a dn and after 10 attempts puts the Dn into DNoutofservice. Do you get the same message when you register the DN 3500 with a desktop toolkit. If so delete the dn from cme and add it again. Follow the Tserver logs so see the registration of this DN. If it's stilll failing then check the config on the PBx itself.

[corn]

Hi dear Genesys users,

everything works with a Genesys 7.0 T-Server of us. We've only the problems in case of
using the Genesys 7.2 T-Server - so I'm not sure if it really makes sense to delete and recreate
the DNs ...

I'm not familiar with ASAI message; but here is the whole part for voice position id 3500 of the
Genesys T-Server trace and the beginning of the registration request for 3501:

14:56:41.084 Trc 04522 Client 528 authorized, name 'Fozzie MOS Genesys 5.00', id=0002:0001
@14:56:41.0840 [0] 7.2.008.01 send_to_client: message EventLinkConnected
AttributeApplicationName 'T-Server_G3si_3'
AttributeSessionID 7405569
AttributeUserData [2] 00 00..
AttributeRegistrationCode 0
AttributeEventSequenceNumber 0000000000000002
AttributeCustomerID 'Resources'
AttributeServerStartTime 452e3b1e000687e0 (14:54:54.428000)
AttributeTimeinuSecs 84000
AttributeTimeinSecs 1160657801 (14:56:41)
14:56:41.084 Trc 04542 EventLinkConnected sent to 528 (0002 Fozzie MOS Genesys 5.00)
14:56:41.084 Trc 04541 RequestRegisterAddress received from 528 (0002 Fozzie MOS Genesys 5.00)
message RequestRegisterAddress
AttributeThisDN '3500'
AttributeRegisterMode 0
AttributeControlMode 0
AttributeAddressType 1 (DN)
AttributeReferenceID 1
map <dn,conf>: find (3500): Ok
[ 4 - ] DN: '3500' Links assigned
(tservice_proc) ControlMode set to 1 for 3500
** ts7.2.008.01[4] <> ** 14:56:41.0840
08 00 00 1B 08 02 00 23 64 96 1C 13 91 A1 10 02 01 03 02 01 C4 40 08 96 49 05 83 33 35 30 B0
=== parsed message ===
prot_discr = 8
CRV = 23
MsgType = 100 (REGISTER)

Facility:  serv_discr = 17(q932_suppl)  fac_ie = component_tag = A1(INVOKE)
invoke_id tag: 02, value = 3
operation tag: 02, value = 196(Domain_Control)
params = q931_tag = 40
list =
Domain:  type = 3(Extension)  address = [4] 33 35 30 30 '3500'

@14:56:41.0840 [0] 7.2.008.01 send_to_client: message EventRegistered
AttributeEventSequenceNumber 0000000000000003
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 84000
AttributeTimeinSecs 1160657801 (14:56:41)
AttributeAddressType 1 (DN)
AttributeExtensions [37] 00 02 01 00..
'AgentStatus' 0
'status' 128
AttributeReferenceID 1
AttributeThisDN '3500'
14:56:41.084 Trc 04542 EventRegistered sent to 528 (0002 Fozzie MOS Genesys 5.00)
@14:56:41.0840 [0] 7.2.008.01 distribute_event: message EventDNOutOfService
AttributeEventSequenceNumber 0000000000000004
AttributeCustomerID 'Resources'
AttributeTimeinuSecs 84000
AttributeTimeinSecs 1160657801 (14:56:41)
AttributeExtensions [17] 00 01 01 00..
'status' 128
AttributeThisDN '3500'
@14:56:41.0840 [ISCC] Debug: Translate: '' -> ''; result 1 ()
14:56:41.084 Trc 04542 EventDNOutOfService sent to 528 (0002 Fozzie MOS Genesys 5.00)
14:56:41.100 Trc 04541 RequestRegisterAddress received from 528 (0002 Fozzie MOS Genesys 5.00)
message RequestRegisterAddress
AttributeThisDN '3501'
AttributeRegisterMode 0
AttributeControlMode 0
AttributeAddressType 1 (DN)
AttributeReferenceID 2
map <dn,conf>: find (3501): Ok
[ 4 - ] DN: '3501' Links assigned
(tservice_proc) ControlMode set to 1 for 3501
** ts7.2.008.01[4] <> ** 14:56:41.1000
08 00 00 1B 08 02 00 24 64 96 1C 13 91 A1 10 02 01 05 02 01 C4 40 08 96 49 05 83 33 35 30 B1
=== parsed message ===
prot_discr = 8
CRV = 24
MsgType = 100 (REGISTER)

Facility:  serv_discr = 17(q932_suppl)  fac_ie = component_tag = A1(INVOKE)
invoke_id tag: 02, value = 5
operation tag: 02, value = 196(Domain_Control)
params = q931_tag = 40
list =
Domain:  type = 3(Extension)  address = [4] 33 35 30 31 '3501'

[victor]

Ok,

We were building a new site which required 7.2 version and I remember that this was one thing I was very concerned with.
I do recall reading a while back that starting from 7.1.xxx ( <-- check Release Notes ) when delay-event-link-connected = false T-Server doesl not wait for reply from PBX about its connection. Instead it will just assumes that it is connected and proceeds. This is why you are getting EventDNOutOfService.

I have a hunch that your PBX does not really reply to your T/S request.


here are some of the things to be aware of:

1. retry-on-proterr = 1 (what is it now? )
Also, have your Avaya engineer look at the HEX you are getting and tell you if there is some sort of error that PBX is returning that causes DNOutOfService.

2. I know you have done it before, but compare options of your TS7.0 and TS7.2 and see if you have something set differently (like asai-protocol-version ). We all have done it more than once.

3. EventDNOutOfService was instituted in TS7.1 so, it means you were probably getting it before, but TS7.0 was ignoring it.

Here is what I suggest:

1. try delay-event-link-connected = true (yes, many of us will gasp at the idea)
2. have your PBX engineer confirm that Avaya is replying to your Connect request

Tell me how it went.

[Fra]

Corn,

could you please upload or email me the full TServer log from the startup till the registration issue?

[corn]

Hi,

sorry for my late answer - I had to analyze another problem ...

Victor, I've tested with changed values for delay-event-link-connected and retry-on-proterr,
but it's the same behaviour as before.
(Because of Avaya expert - there's none - another colleague and I have to solve this "alone".)

Regards,
  Corn