Музыка на удержании.

[veulk1]

Пропала музыка на удержании.
Работало все около года.Файл на месте.В логах обращается к правильному адресу. Антивирусы отключал.Все сервисы запущены.
Не работает, включая внутренние вызовы между абонентами АТС.

10:10:56.745|MediaServer.cpp(1587)|Trace5||??:EndPoint [email protected]:5482 removed from call [email protected]:5482
10:10:56.759|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:10:56.927|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=801 current=560
10:10:57.247|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=714 current=640
10:10:57.567|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=636 current=560
10:10:57.652|MSEndPoint.cpp(892)|Trace5||??:EndPoint [email protected]:5482 destroyed
10:10:57.652|MSEndPoint.cpp(893)|Trace5||??:EndPoint [email protected]:5482 destroyed statistics:
Begin send:0
LastSent:0
TotalSent:0
MaxSendInterval:0
MinSendInterval:0
AvgSendInterval:0
SendDeviation:0
Begin recv:0
Last recv:0
TotalRecv:0
MaxRecvInterval:0
MinRecvInterval:0
AvgRecvInterval:0
ReceiveDeviation:0

10:10:57.887|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=539 current=640
10:10:57.957|MSEndPoint.cpp(1342)|Debug2||??:EP:[email protected]:5482 MixPos return: need 88 available 80
10:11:00.444|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=492 current=568
10:11:00.764|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=492 current=648
10:11:02.684|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=770 current=568
10:11:03.004|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=872 current=968
10:11:03.324|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=913 current=888
10:11:03.644|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=855 current=968
10:11:03.820|MediaServer.cpp(1587)|Trace5||??:EndPoint [email protected]:5482 removed from call [email protected]:5482
10:11:03.826|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:11:03.866|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:11:03.866|MediaServer.cpp(1720)|Trace5||??:references to call [email protected]:5482 were removed
10:11:03.964|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=775 current=888
10:11:04.295|MSEndPoint.cpp(1342)|Debug2||??:EP:[email protected]:5482 MixPos return: need 88 available 8
10:11:04.650|MSCallConf.cpp(32)|Trace5||??:Call: [email protected]:5482 destroyed
10:11:04.906|MSEndPoint.cpp(892)|Trace5||??:EndPoint [email protected]:5482 destroyed
10:11:04.906|MSEndPoint.cpp(893)|Trace5||??:EndPoint [email protected]:5482 destroyed statistics:
Begin send:0
LastSent:0
TotalSent:0
MaxSendInterval:0
MinSendInterval:0
AvgSendInterval:0
SendDeviation:0
Begin recv:0
Last recv:0
TotalRecv:0
MaxRecvInterval:0
MinRecvInterval:0
AvgRecvInterval:0
ReceiveDeviation:0

10:11:04.906|MSEndPoint.cpp(892)|Trace5||??:EndPoint [email protected]:5482 destroyed
10:11:04.906|MSEndPoint.cpp(893)|Trace5||??:EndPoint [email protected]:5482 destroyed statistics:
Begin send:0
LastSent:0
TotalSent:0
MaxSendInterval:0
MinSendInterval:0
AvgSendInterval:0
SendDeviation:0
Begin recv:0
Last recv:0
TotalRecv:0
MaxRecvInterval:0
MinRecvInterval:0
AvgRecvInterval:0
ReceiveDeviation:0

10:11:05.244|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1339 current=1920
10:11:05.564|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1725 current=2000
10:11:05.885|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=2120 current=1920
10:11:06.205|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=2067 current=2000
10:11:06.516|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=338 current=392
10:11:06.525|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1997 current=1920
10:11:06.845|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1922 current=2000
10:11:07.165|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1842 current=1920
10:11:07.485|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1770 current=1840
10:11:07.805|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1665 current=1920
10:11:08.125|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1585 current=1840
10:11:08.445|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1505 current=960
10:11:08.765|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1422 current=1040
10:11:09.086|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1367 current=960
10:11:09.406|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1282 current=1040
10:11:09.726|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1192 current=960
10:11:10.046|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1107 current=1040
10:11:10.366|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=1027 current=960
10:11:10.686|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=942 current=1040
10:11:11.006|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=872 current=960
10:11:11.326|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=787 current=1040
10:11:11.646|MSEndPoint.cpp(3728)|Debug2||??:[email protected]:5482(shift toMix) avgJitter=707 current=960
10:11:12.698|MSEndPoint.cpp(1342)|Debug2||??:EP:[email protected]:5482 MixPos return: need 88 available 80
10:11:12.810|MediaServer.cpp(1587)|Trace5||??:EndPoint [email protected]:5482 removed from call [email protected]:5482
10:11:12.812|MediaServer.cpp(1434)|Trace5||??:EP [email protected]:5482. Stop to record file F:\Recordings\1367\[%D0%9A%D0%B0%D0%B7%D0%B0%D1%85%D1%81%D1%82%D0%B0%D0%BD %D0%A1%D0%BE%D1%82%D1%80%D1%83%D0%B4%D0%BD%D0%B8%D0%BA2]_1367-810998935775420_20150907071052(1482).wav
10:11:12.812|MediaServer.cpp(1598)|Trace5||??:EndPoint [email protected]:5482 removed from call [email protected]:5482
10:11:12.813|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:11:12.813|VirtualEndPoint.cpp(12)|Trace5||??:Virtual EndPoint [email protected]:5482 destroyed
10:11:12.814|MediaServer.cpp(1587)|Trace5||??:EndPoint [email protected]:5482 removed from call [email protected]:5482
10:11:12.815|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:11:13.130|MediaServer.cpp(1338)|Trace5||??:references to EndPoint [email protected]:5482 were removed
10:11:13.130|MediaServer.cpp(1720)|Trace5||??:references to call [email protected]:5482 were removed
10:11:13.653|MSCallConf.cpp(32)|Trace5||??:Call: [email protected]:5482 destroyed
10:11:13.653|MSEndPoint.cpp(892)|Trace5||??:EndPoint [email protected]:5482 destroyed
10:11:13.653|MSEndPoint.cpp(893)|Trace5||??:EndPoint [email protected]:5482 destroyed statistics:
Begin send:258486277
LastSent:258537664
TotalSent:2569
MaxSendInterval:32
MinSendInterval:15
AvgSendInterval:20.0027
SendDeviation:7.03645
Begin recv:258486823
Last recv:258537602
TotalRecv:2543
MaxRecvInterval:312
MinRecvInterval:0
AvgRecvInterval:19.9682
ReceiveDeviation:42.3153

10:11:13.653|MSEndPoint.cpp(892)|Trace5||??:EndPoint [email protected]:5482 destroyed
10:11:13.653|MSEndPoint.cpp(893)|Trace5||??:EndPoint [email protected]:5482 destroyed statistics:
Begin send:258486277
LastSent:258537648
TotalSent:2569
MaxSendInterval:47
MinSendInterval:0
AvgSendInterval:19.9965
SendDeviation:7.0595
Begin recv:258517462
Last recv:258537508
TotalRecv:1002
MaxRecvInterval:47
MinRecvInterval:0
AvgRecvInterval:20.006
ReceiveDeviation:7.69397

10:11:18.701|MSEndPoint.cpp(962)|Trace5||??:Best route for 192.168.106.147 is:
dwForwardDest=192.168.104.0
dwForwardMask=255.255.252.0
dwForwardNextHop=0.0.0.0
dwForwardIfIndex=13
dwForwardType=3

10:11:18.702|MSEndPoint.cpp(805)|Trace5||??:[email protected]:5482: RTP bind address 192.168.105.111:7066
10:11:18.702|MSEndPoint.cpp(816)|Trace5||??:[email protected]:5482: RTCP bind address 192.168.105.111:7067
10:11:18.703|MMFileReader.cpp(1159)|Trace5||??:c:\programdata\3cx\data\ivr\prompts\vremena12_ok.wav taken from the cache
10:11:18.703|MediaServer.cpp(1064)|Trace5||??:EndPoint created: (destination=192.168.106.147)
EndPoint: [email protected]:5482(LOCAL)
LOGID=C:1484.1 Status: MSEP_LOCAL
RTP:192.168.105.111:7066
RTCP:192.168.105.111:7067
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

10:11:18.704|MediaServer.cpp(1540)|Trace5||??:EP [email protected]:5482 joined to call [email protected]:5482
10:11:18.704|MediaServer.cpp(1549)|Trace5||??:starting send on new call [email protected]:5482
10:11:18.706|MediaServer.cpp(1161)|Trace5||??:Set Party EP:C:1484.1SDP:v=0
o=- 1199331817 1199331817 IN IP4 192.168.106.147

 

[veulk1]

В логах медиа сервера постояно одна и та же ошибка
10:10:21.512|MSEndPoint.cpp(2712)|Trace5||??:[MS505003] C:1479.1: RTP stream from XX.XX.XX.XX:8000 restored.
10:10:21.512|MSEndPoint.cpp(2704)|Trace5||??:[MS505002] C:1479.1: Failed to receive incoming stream from XX.XX.XX.XX:8000
WSAError=10054
10:10:21.528|MSEndPoint.cpp(2712)|Trace5||??:[MS505003] C:1479.1: RTP stream from XX.XX.XX.XX:8000 restored.
10:10:21.530|MSEndPoint.cpp(2704)|Trace5||??:[MS505002] C:1479.1: Failed to receive incoming stream from XX.XX.XX.XX:8000 WSAError=10054

 

[veulk1]

Вот что пишет при перезапуске медиасервера

015/09/07 >>
10:50:35.577|MediaServer.cpp(726)|Log2||??rocess priority class has been set to 128
10:50:35.577|MediaServer.cpp(645)|Log2||??:The number of RTP senders is set to 4
10:50:35.578|MediaServer.cpp(664)|Log2||??:RTP sender[0]: use default thread settings
10:50:35.578|MediaServer.cpp(664)|Log2||??:RTP sender[1]: use default thread settings
10:50:35.578|MediaServer.cpp(664)|Log2||??:RTP sender[2]: use default thread settings
10:50:35.579|MediaServer.cpp(664)|Log2||??:RTP sender[3]: use default thread settings
10:50:35.579|RTPSender.cpp(386)|Trace5||??:RTPSenders::RTPSenders: size=4
10:50:35.579|RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[0]: Enter
10:50:35.579|RTPSender.cpp(56)|Trace5||??:RTPSender::RTPSender[0]: thread created
10:50:35.580|RTPSender.cpp(67)|Trace5||??:RTPSender::RTPSender[0]: Done
10:50:35.580|RTPSender.cpp(398)|Trace5||??:RTPSenders::RTPSenders: sender[0] is valid
10:50:35.580|RTPSender.cpp(400)|Trace5||??:RTPSenders::RTPSenders: sender[0] added
10:50:35.580|RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[1]: Enter
10:50:35.580|RTPSender.cpp(56)|Trace5||??:RTPSender::RTPSender[1]: thread created
10:50:35.580|RTPSender.cpp(67)|Trace5||??:RTPSender::RTPSender[1]: Done
10:50:35.580|RTPSender.cpp(398)|Trace5||??:RTPSenders::RTPSenders: sender[1] is valid
10:50:35.580|RTPSender.cpp(400)|Trace5||??:RTPSenders::RTPSenders: sender[1] added
10:50:35.580|RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[2]: Enter
10:50:35.581|RTPSender.cpp(56)|Trace5||??:RTPSender::RTPSender[2]: thread created
10:50:35.581|RTPSender.cpp(67)|Trace5||??:RTPSender::RTPSender[2]: Done
10:50:35.581|RTPSender.cpp(398)|Trace5||??:RTPSenders::RTPSenders: sender[2] is valid
10:50:35.581|RTPSender.cpp(400)|Trace5||??:RTPSenders::RTPSenders: sender[2] added
10:50:35.581|RTPSender.cpp(53)|Trace5||??:RTPSender::RTPSender[3]: Enter
10:50:35.581|RTPSender.cpp(56)|Trace5||??:RTPSender::RTPSender[3]: thread created
10:50:35.581|RTPSender.cpp(67)|Trace5||??:RTPSender::RTPSender[3]: Done
10:50:35.581|RTPSender.cpp(398)|Trace5||??:RTPSenders::RTPSenders: sender[3] is valid
10:50:35.581|RTPSender.cpp(400)|Trace5||??:RTPSenders::RTPSenders: sender[3] added
10:50:35.582|MediaServer.cpp(562)|Log2||??:The number of RTP receivers is set to 4
10:50:35.582|MediaServer.cpp(582)|Log2||??:RTP receiver[0]: use default thread settings
10:50:35.582|MediaServer.cpp(582)|Log2||??:RTP receiver[1]: use default thread settings
10:50:35.582|MediaServer.cpp(582)|Log2||??:RTP receiver[2]: use default thread settings
10:50:35.582|MediaServer.cpp(582)|Log2||??:RTP receiver[3]: use default thread settings
10:50:35.595|MMFileReader.cpp(20)|Trace5||??:CoInitializeEx called for thread 4860.Returned value 0x0
10:50:35.808|Service.cpp(419)|Log2||??:*** Initialize ***
10:50:35.813|MediaServer.cpp(174)|Log2||??reload cached settings
10:50:35.813|Service.cpp(449)|Trace5||??:Cached parameters has been set:=====[00000000006DBEB0]
MOH=C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav
MUSICONHOLDFILE=C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav
LOCALADDR=
EXTADDR=
EXTIF=192.168.106.55
MS_ALLOWVIDEOANDIMAGEPROXY=1
ADD2833=1
ANSP=1
TOS=0
CS=62914560
MCFS=5242880
FLP=7000
LLP=7499
FEP=9000
LEP=9049
USELINEIN=0
LINEINGUID=
allowExternalOn=0.0.0.0/0
externalIPRange=
allowSourceAsOutbound=1
reportSourceConflicts=0
STUNTOUT=3000
MS_BLINDEXTPORTS=0
STUN=ARRAY
[0]=stun.3cx.com:3478

[1]=stun2.3cx.com:3478

[2]=stun3.3cx.com:3478

=================================

10:50:35.872|Service.cpp(513)|Log2||??:Service Started
10:50:35.874|Service.cpp(119)|Log2||??:*** Connecting to CM at[127.0.0.1:5482] ***
10:50:35.876|Service.cpp(123)|Log2||??:*** Connected to 3CX:5482/CallManager at [127.0.0.1:5482] ***
10:50:35.877|Service.cpp(576)|Trace5||??arametersUpdated:=====[00000000006DC1C0]
MOH=C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav
MUSICONHOLDFILE=C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav
LOCALADDR=
EXTADDR=
EXTIF=192.168.106.55
MS_ALLOWVIDEOANDIMAGEPROXY=1
ADD2833=1
ANSP=1
TOS=0
CS=62914560
MCFS=5242880
FLP=7000
LLP=7499
FEP=9000
LEP=9049
USELINEIN=0
LINEINGUID=
allowExternalOn=0.0.0.0/0
externalIPRange=
allowSourceAsOutbound=1
reportSourceConflicts=0
STUNTOUT=3000
MS_BLINDEXTPORTS=0
STUN=ARRAY
[0]=stun.3cx.com:3478

[1]=stun2.3cx.com:3478

[2]=stun3.3cx.com:3478

=================================

10:50:35.878|MediaServer.cpp(145)|Trace5||??:ini file section of media server settings stored
10:50:36.870|FileCache.cpp(427)|Trace5||??:Caching prompt C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav...
10:50:36.870|MMFileReader.cpp(20)|Trace5||??:CoInitializeEx called for thread 3704.Returned value 0x0
10:50:36.936|MMFileReader.cpp(1206)|Trace5||??:c:\programdata\3cx\data\ivr\prompts\vremena12_ok.wav opened as DirectShow stream
10:50:37.100|FileCache.cpp(429)|Trace5||??:Caching prompt C:\ProgramData\3CX\Data\Ivr\Prompts\vremena12_ok.wav done. Size:4486400 bytes
10:50:42.575|MediaServer.cpp(1342)|Error1||??:Endpoint [email protected]:5482 is not found!
10:50:42.677|MediaServer.cpp(1342)|Error1||??:Endpoint [email protected]:5482 is not found!
10:50:42.677|MediaServer.cpp(1342)|Error1||??:Endpoint [email protected]:5482 is not found!
10:50:42.677|MediaServer.cpp(1724)|Trace5||??:call [email protected]:5482 not found
10:50:45.355|MSEndPoint.cpp(962)|Trace5||??:Best route for 192.168.107.168 is:
dwForwardDest=192.168.104.0
dwForwardMask=255.255.252.0
dwForwardNextHop=0.0.0.0
dwForwardIfIndex=13
dwForwardType=3

10:50:45.358|MSEndPoint.cpp(805)|Trace5||??:[email protected]:5482: RTP bind address 192.168.105.111:7000
10:50:45.358|MSEndPoint.cpp(816)|Trace5||??:[email protected]:5482: RTCP bind address 192.168.105.111:7001
10:50:45.358|MMFileReader.cpp(1159)|Trace5||??:c:\programdata\3cx\data\ivr\prompts\vremena12_ok.wav taken from the cache
10:50:45.425|MediaServer.cpp(1064)|Trace5||??:EndPoint created: (destination=192.168.107.168)
EndPoint: [email protected]:5482(LOCAL)
LOGID=C:1567.1 Status: MSEP_LOCAL
RTP:192.168.105.111:7000
RTCP:192.168.105.111:7001
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

10:50:45.427|MediaServer.cpp(1540)|Trace5||??:EP [email protected]:5482 joined to call [email protected]:5482
10:50:45.427|MediaServer.cpp(1549)|Trace5||??:starting send on new call [email protected]:5482
10:50:45.430|MediaServer.cpp(1161)|Trace5||??:Set Party EP:C:1567.1SDP:v=0

 

[veulk1]

И еще один момент в логах IVR Servera:
:02:36.935|2920|VXIMachine.cpp(1072):IvrDll, CallSession:rompts_Play(), Play Queued files
11:02:38.077|2920|VXIMachine.cpp(806):IvrDll, CallSession::RegisterPrompt(), Added prompt CrogramDataCataIvrPromptsremena12_ok.wav

Как будто искажено имя конечного файла.
Как решить данную проблему?

 

[veulk1]

Перезагрузил сервер и проблема не ушла.
В логе в момент поставноки на удержании вижу следующее :

08-сен-2015 08:34:56.786 NAT/ALG check:L:70.2[Extn:1393] REQUEST 'INVITE' - some of SIP/SDP headers may contain inconsistent information or modified by intermediate hop
Media session IP ('c=' attribute) is not equal to the IP specified in contact header:
Media session IP:0.0.0.0
Contact IP:192.168.106.126
Media session IP ('c=' attribute) is not equal to the SIP packet source(IPort):
Media session IP: 0.0.0.0
Received from: 192.168.106.126

 

[igorsnezhko]

Проверьте, не появились ли у вас на сервере (или клиенте, у которого возникает проблема) новые физические или виртуальные сетевые интерфейсы.

 

[veulk1]

проблему локализовали, пока победить не удалось
Удержание работает в случае внешнего звонка, а на внутренних нет, хотя в записи разговоров удержании проигрывается, но телефоне тишина.

 

[igorsnezhko]

Вы так и не ответили про интерфейсы.

 

[veulk1]

Интерефейсов новых не появилось.Все в штатном режиме с сетевой точки зрения.

 

[igorsnezhko]

А у вас какие телефоны внутри стоят?

 

[veulk1]

yealink t21p e2 по автонастройке, panasonic tgp500,ut123/133 на всех так.

 

[igorsnezhko]

И это на всех телефонах или на определённых?

 

[veulk1]

на всех, именно глобально

 

[igorsnezhko]

Поиграйтесь на внутренних номерах пользователей (Extensions) в разделе Другие. Пддержка Re-Invite и Поддержка Replaces. А вообще, хорошо бы понимать вашу топологию. Есть у меня подозрение что в сети что-то глобально не так настроено.