Opened 8 years ago

Closed 8 years ago

#308 closed баг (fixed)

Теряется и не восстанавливается соединение ESL

Reported by: alx Owned by: dimag
Priority: major Milestone: 1 очередь
Component: ПО MC04-Dispatcher. Пульт диспетчера/техника Keywords: reconnect
Cc: san

Description

В r339 под FreeBSD наблюдается странное поведение программы:

  1. Запускаю программу.
  2. Ввожу логин 2@192.168.0.63 и пароль, нажимаю Enter.

Программа успашно устанавливает соединение ESL и около секунды активно обмениваетя информацией с сервером, после чего разрывает соединение. После разрыва программа немедленно устанавливает новое соединение, получает от коммутатора Content-Type: auth/request и... молчит. При этом никаких окон на дисплее нет. Через 25 секунд, не дождавшися аутентификации, коммутатор говорит:

Content-Type: text/disconnect-notice
Content-Length: 67

Disconnected, goodbye.
See you at ClueCon! http://www.cluecon.com/

и рвет соединение. Наш пульт рисует главное окно со списком конференций и пользователей и надписью "Отсутствует подключение к сети" на красном фоне. Повторных подключений по ESL к коммутатору программа не делает. Вот что программа пишет в консоль:

/usr/local/lib/qt4/plugins

rootStartElement
Characters
15:35:06.564 os_core_unix.c !pjlib 2.5.1 for POSIX initialized
8013003
libpng warning: iCCP: known incorrect sRGB profile
UP 0 years, 1 day, 0 hours, 40 minutes, 48 seconds, 381 milliseconds, 451 microseconds
FreeSWITCH (Version 1.6.9 git d574870 2016-06-13 18:10:44Z 64bit) is ready
133 session(s) since startup
0 session(s) - peak 11, last 5min 0
0 session(s) per Sec out of max 30, peak 9, last 5min 0
1000 session(s) max
min idle cpu 0.00/99.77
Current Stack Size/Max 240K/8192K
15:35:07.782 sip_endpoint.c !.Creating endpoint instance...
15:35:07.783          pjlib  .select() I/O Queue created (0x80cf32028)
15:35:07.783 sip_endpoint.c  .Module "mod-msg-print" registered
15:35:07.783 sip_transport.  .Transport manager created.
15:35:07.783   pjsua_core.c  .PJSUA state changed: NULL --> CREATED
WARNING: no real random source present!
15:35:07.790   pjsua_core.c  .pjsua version 2.5.1 for FreeBSD-9.3/amd64 initialized
15:35:07.790   pjsua_core.c  bind() error: áÄÒÅÓ ÕÖÅ ÉÓÐÏÌØÚÕÅÔÓÑ [status=120048]
[2016/08/19 15:35:07.791466, 2] ssh_connect:  libssh 0.7.3 (c) 2003-2014 Aris Adamantiadis, Andreas Schneider, and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_noop
[2016/08/19 15:35:07.791617, 2] ssh_socket_connect:  Nonblocking connection socket: 17
[2016/08/19 15:35:07.791653, 2] ssh_connect:  Socket connecting, now waiting for the callbacks to work
[2016/08/19 15:35:07.791770, 1] socket_callback_connected:  Socket connection callback: 1 (0)
[2016/08/19 15:35:07.830150, 1] ssh_client_connection_callback:  SSH server banner: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu1
[2016/08/19 15:35:07.830180, 1] ssh_analyze_banner:  Analyzing banner: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu1
[2016/08/19 15:35:07.830197, 1] ssh_analyze_banner:  We are talking to an OpenSSH client version: 7.2 (70200)
[2016/08/19 15:35:07.880129, 2] ssh_packet_dh_reply:  Received SSH_KEXDH_REPLY
[2016/08/19 15:35:07.885298, 2] ssh_client_curve25519_reply:  SSH_MSG_NEWKEYS sent
[2016/08/19 15:35:07.885371, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[2016/08/19 15:35:07.885743, 2] ssh_packet_newkeys:  Signature verified and valid
15:35:07.944    pjsua_acc.c  ....sip:2@192.168.0.63: registration success, status=200 (OK), will re-register in 300 seconds
Startup dlg  finished
ESL Connected
 Window Icon setted
MainAppFrameWindow2 ctor
pLogViewWidget created
pSplitterSoundPlay created
Main Window created
ESL Reconnect fail

Вот дамп второго подключения:

15:13:46.367056 IP 192.168.0.75.12611 > 192.168.0.63.8021: Flags [S], seq 2182638936, win 65535, options [mss 1460,nop,wscale 6,sackOK,TS val 2948457413 ecr 0], length 0
E..<..@.@.$....K...?1C.U..mX.......................
........
15:13:46.367128 IP 192.168.0.63.8021 > 192.168.0.75.12611: Flags [S.], seq 2301299142, ack 2182638937, win 28960, options [mss 1460,sackOK,TS val 21824836 ecr 2948457413,nop,wscale 9], length 0
E..<..@.@......?...K.U1C.+      ...mY..q ...........
.M.D.......
15:13:46.367171 IP 192.168.0.75.12611 > 192.168.0.63.8021: Flags [.], ack 1, win 1040, options [nop,nop,TS val 2948457413 ecr 21824836], length 0
E..4..@.@.$....K...?1C.U..mY.+  ............
.....M.D
15:13:46.367590 IP 192.168.0.63.8021 > 192.168.0.75.12611: Flags [P.], seq 1:29, ack 1, win 57, options [nop,nop,TS val 21824836 ecr 2948457413], length 28
E..P..@.@..J...?...K.U1C.+      ...mY...9.P.....
.M.D....Content-Type: auth/request


15:13:46.467046 IP 192.168.0.75.12611 > 192.168.0.63.8021: Flags [.], ack 29, win 1040, options [nop,nop,TS val 2948457513 ecr 21824836], length 0
E..4..@.@.$....K...?1C.U..mY.+  ......A.....
...).M.D

15:14:11.019637 IP 192.168.0.63.8021 > 192.168.0.75.12611: Flags [P.], seq 29:86, ack 1, win 57, options [nop,nop,TS val 21830999 ecr 2948457513], length 57
E..m..@.@..,...?...K.U1C.+      ...mY...9L......
.M.W...)Content-Type: text/disconnect-notice
Content-Length: 67


15:14:11.019668 IP 192.168.0.63.8021 > 192.168.0.75.12611: Flags [FP.], seq 86:153, ack 1, win 57, options [nop,nop,TS val 21830999 ecr 2948457513], length 67
E..w..@.@..!...?...K.U1C.+
...mY...9.......
.M.W...)Disconnected, goodbye.
See you at ClueCon! http://www.cluecon.com/

15:14:11.019689 IP 192.168.0.75.12611 > 192.168.0.63.8021: Flags [.], ack 154, win 1038, options [nop,nop,TS val 2948482066 ecr 21830999], length 0
E..4..@.@."....K...?1C.U..mY.+
`....
......
..D..M.W
15:14:11.019817 IP 192.168.0.75.12611 > 192.168.0.63.8021: Flags [F.], seq 1, ack 154, win 1038, options [nop,nop,TS val 2948482066 ecr 21830999], length 0
E..4..@.@."....K...?1C.U..mY.+
`....
......
..D..M.W
15:14:11.019928 IP 192.168.0.63.8021 > 192.168.0.75.12611: Flags [.], ack 2, win 57, options [nop,nop,TS val 21830999 ecr 2948482066], length 0
E..4_.@.@.Y2...?...K.U1C.+
`..mZ...9.......
.M.W..D.

Что ожидалось:

  1. что программа, один раз успешно подключившись к коммутатору, будет использовать это соединение до конца сеанса работы. Зачем пульт разрывает существующее соединение и немедленно устанавливает новое, непонятно;
  2. что установив второе соединение и получив запрос auth/request, пульт передаст свой пароль и продолжит работу;
  3. наконец, что потеряв подключение к коммутатору, программа будет (как минимум) пытаться его восстановить.

Change History (26)

comment:1 by alx, 8 years ago

См. также #254 возможно, это оно же?

comment:2 by dimag, 8 years ago

Нет это не #254

comment:3 by dimag, 8 years ago

Вы запускали программу на машине без устройства аудио ввода/вывода, на что программа не рассчитана. Программа требует для своей работы устройство аудио. Если его нет, товсё будет нормально отрисовываться, но конференция не будет организовываться, так как будет невозможно разговарить и слушать.

Установите на тестовой машине аудио-адаптер.

in reply to:  3 comment:4 by alx, 8 years ago

Replying to dimag:

Вы запускали программу на машине без устройства аудио ввода/вывода,

С чего Вы это взяли? Аудио устройство в машине есть.

Установите на тестовой машине аудио-адаптер.

Какова роль аудио-адаптера в процессе установления/разрыва соединения ESL?

Last edited 8 years ago by alx (previous) (diff)

comment:5 by dimag, 8 years ago

Непонятно данное сообщение
15:35:07.790 pjsua_core.c bind() error: áÄÒÅÓ ÕÖÅ ÉÓÐÏÌØÚÕÅÔÓÑ [status=120048].
Что символы áÄÒÅÓ ÕÖÅ ÉÓÐÏÌØÚÕÅÔÓÑ означают?

in reply to:  5 comment:6 by alx, 8 years ago

Replying to dimag:

Непонятно данное сообщение

Прошу прощения, текст испортился при копировании. Здесь выводится:

15:35:07.790 pjsua_core.c bind() error: Адрес уже используется [status=120048].

comment:7 by dimag, 8 years ago

Эта ошибка постоянно повторяется?

in reply to:  7 comment:8 by alx, 8 years ago

Replying to dimag:

Эта ошибка постоянно повторяется?

Не знаю, о какой ошибке Вы говорите - об "Адрес уже используется" или о той, которой посвящен этот тикет. Но и та, и другая возникает при каждом запуске программы.

comment:9 by alx, 8 years ago

Обнаружил одну из причин невосстановления потерянного соединения.

В классе ESL есть строка sHost, которая инициализируется пустым значением.

В методе ESL::Connect() сначала выполняется esl_connect(), и в случае ее успешного выполнения sHost получает непустое значение.

Метод ESL::Reconnect() выполняет повторную попытку соединения только если значение sHost непустое.

Таким образом, если esl_connect() завершится неуспешно, ESL::Reconnect() не будет ничего делать.

comment:10 by dimag, 8 years ago

Воспроизводиться ли ошибка в r382 и более поздних? Возможна причина в том, что запрошенный порт 5060 по умолчанию был занят другой программой.
Начиная с r382 порт выбирается автоматически и сообщение "Дрес уже используется" не должно проявляться.

in reply to:  10 comment:11 by alx, 8 years ago

Replying to dimag:

Воспроизводиться ли ошибка в r382 и более поздних?

Какая именно? "Адрес уже используется"? Нет, не воспроизводится.

comment:12 by dimag, 8 years ago

Если так то данный тикет можно закрыть, судя по сообщениям проблема возникла из того что адрес и порт были заняты(например другим SIP-клиентом).

in reply to:  12 comment:13 by alx, 8 years ago

Replying to dimag:

Если так то данный тикет можно закрыть,

Объясните, пожалуйста, почему его можно закрыть, и с какой резолюцией Вы предлагаете его закрыть.

comment:14 by san, 8 years ago

Milestone: Текущее1 очередь

comment:15 by dimag, 8 years ago

Потому что причина приводящая к данной ошибке, когда по умолчанию выбирался порт 5060 для SIP и я не как не обрабатывал ошибку при создания транспорта устраненна.
Предлогая закрыть с резолюуией fixed.

in reply to:  15 comment:16 by alx, 8 years ago

Replying to dimag:

Потому что причина ... устраненна.
Предлогая закрыть с резолюуией fixed.

  1. Начиная с какой ревизии она устранена?
  2. В чем конкретно заключалась проблема (ее причина)? Ваш comment:15 я просто не понял: какая связь между SIP транспортом и подключением к event-socket'у?
  3. Как Вы ее устранили?
  4. Почему в последней имеющейся на данный момент в репозитории r396 я наблюдаю те же самые симптомы?
Last edited 8 years ago by alx (previous) (diff)

comment:17 by dimag, 8 years ago

В ревизии r405 наблюдается подобное поведение?
С какими настройками SIP-порта и медиапорта вы проводите тестирование?

in reply to:  17 comment:18 by alx, 8 years ago

Replying to dimag:

В ревизии r405 наблюдается подобное поведение?

Да. С одним уточнением - пункт 3 из описания тикета теперь выполняется. То есть после 25 секунд таймаута FS закрывает соединение со своей стороны, после чего пульт переустанавливает его. Переподключаться стало, насколько я понимаю, после changeset:389.

С какими настройками SIP-порта и медиапорта вы проводите тестирование?

SIP-порт: пусто. Медиапорт: пусто. Думаете, настройки SIP могут как-то влиять на установку соединения ESL?

comment:19 by dimag, 8 years ago

Можете снова вывести лог выводимый программой.

in reply to:  19 comment:20 by alx, 8 years ago

Replying to dimag:

Можете снова вывести лог выводимый программой.

Спасибо. :)

alx% ./MC04Dispatcher
/usr/local/lib/qt4/plugins
main.log.2016-09-06.log

rootStartElement
Characters
18:03:57.429 os_core_unix.c !pjlib 2.5.1 for POSIX initialized
8013003
libpng warning: iCCP: known incorrect sRGB profile
UP 0 years, 0 days, 14 hours, 55 minutes, 19 seconds, 634 milliseconds, 710 microseconds
FreeSWITCH (Version 1.6.10 git 726448d 2016-08-24 21:54:04Z 64bit) is ready
3558 session(s) since startup
0 session(s) - peak 7, last 5min 3
0 session(s) per Sec out of max 30, peak 11, last 5min 2
1000 session(s) max
min idle cpu 0.00/98.63
Current Stack Size/Max 240K/8192K
18:04:02.453 sip_endpoint.c !.Creating endpoint instance...
18:04:02.454          pjlib  .select() I/O Queue created (0x80dc15028)
18:04:02.454 sip_endpoint.c  .Module "mod-msg-print" registered
18:04:02.454 sip_transport.  .Transport manager created.
18:04:02.454   pjsua_core.c  .PJSUA state changed: NULL --> CREATED
18:04:02.454 sip_endpoint.c  .Module "mod-pjsua-log" registered
18:04:02.454 sip_endpoint.c  .Module "mod-tsx-layer" registered
18:04:02.454 sip_endpoint.c  .Module "mod-stateful-util" registered
18:04:02.455 sip_endpoint.c  .Module "mod-ua" registered
18:04:02.455 sip_endpoint.c  .Module "mod-100rel" registered
18:04:02.455 sip_endpoint.c  .Module "mod-pjsua" registered
18:04:02.455 sip_endpoint.c  .Module "mod-invite" registered
18:04:02.472       pa_dev.c  ..PortAudio sound library initialized, status=0
18:04:02.472       pa_dev.c  ..PortAudio host api count=1
18:04:02.472       pa_dev.c  ..Sound device count=2
18:04:02.479          pjlib  ..select() I/O Queue created (0x80deda028)
WARNING: no real random source present!
18:04:02.483 sip_endpoint.c  .Module "mod-evsub" registered
18:04:02.483 sip_endpoint.c  .Module "mod-presence" registered
18:04:02.483 sip_endpoint.c  .Module "mod-mwi" registered
18:04:02.483 sip_endpoint.c  .Module "mod-refer" registered
18:04:02.483 sip_endpoint.c  .Module "mod-pjsua-pres" registered
18:04:02.483 sip_endpoint.c  .Module "mod-pjsua-im" registered
18:04:02.483 sip_endpoint.c  .Module "mod-pjsua-options" registered
18:04:02.483   pjsua_core.c  .1 SIP worker threads created
18:04:02.483   pjsua_core.c  .pjsua version 2.5.1 for FreeBSD-9.3/amd64 initialized
18:04:02.483   pjsua_core.c  .PJSUA state changed: CREATED --> INIT
18:04:02.483   pjsua_core.c  SIP UDP socket reachable at 192.168.0.75:62826
18:04:02.483 udp0x80e162800  SIP UDP transport started, published address is 192.168.0.75:62826
18:04:02.483    tcptp:62826  SIP TCP listener ready for incoming connections at 192.168.0.75:62826
18:04:02.483   pjsua_core.c  PJSUA state changed: INIT --> STARTING
18:04:02.483 sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
18:04:02.483   pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
[2016/09/07 18:04:02.484470, 2] ssh_connect:  libssh 0.7.3 (c) 2003-2014 Aris Adamantiadis, Andreas Schneider, and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_noop
[2016/09/07 18:04:02.484607, 2] ssh_socket_connect:  Nonblocking connection socket: 18
[2016/09/07 18:04:02.484616, 2] ssh_connect:  Socket connecting, now waiting for the callbacks to work
[2016/09/07 18:04:02.484800, 1] socket_callback_connected:  Socket connection callback: 1 (0)
[2016/09/07 18:04:02.523063, 1] ssh_client_connection_callback:  SSH server banner: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.1
[2016/09/07 18:04:02.523093, 1] ssh_analyze_banner:  Analyzing banner: SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.1
[2016/09/07 18:04:02.523110, 1] ssh_analyze_banner:  We are talking to an OpenSSH client version: 7.2 (70200)
[2016/09/07 18:04:02.570637, 2] ssh_packet_dh_reply:  Received SSH_KEXDH_REPLY
[2016/09/07 18:04:02.575712, 2] ssh_client_curve25519_reply:  SSH_MSG_NEWKEYS sent
[2016/09/07 18:04:02.575726, 2] ssh_packet_newkeys:  Received SSH_MSG_NEWKEYS
[2016/09/07 18:04:02.576101, 2] ssh_packet_newkeys:  Signature verified and valid
18:04:02.631    pjsua_acc.c  Adding account: id=sip:2@192.168.0.63
18:04:02.631    pjsua_acc.c  .Account sip:2@192.168.0.63 added with id 0
18:04:02.631    pjsua_acc.c  .Acc 0: setting registration..
18:04:02.632   pjsua_core.c  ...TX 487 bytes Request msg REGISTER/cseq=43258 (tdta0x80de77000) to UDP 192.168.0.63:5060:
REGISTER sip:192.168.0.63 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.75:62826;rport;branch=z9hG4bKPj9536a08e-1b7e-4f6e-8e97-fbbc3ddeb484
Max-Forwards: 70
From: <sip:2@192.168.0.63>;tag=ec1b8fad-4389-4d8d-bf31-ad9642fd6732
To: <sip:2@192.168.0.63>
Call-ID: 01a0d3fe-d2b4-4de0-8963-c902898a1f73
CSeq: 43258 REGISTER
Contact: <sip:2@192.168.0.75:62826;ob>
Expires: 200
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
18:04:02.632    pjsua_acc.c  ..Acc 0: Registration sent
18:04:02.633   pjsua_core.c  .RX 674 bytes Response msg 401/REGISTER/cseq=43258 (rdata0x80cf2e028) from UDP 192.168.0.63:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.0.75:62826;rport=62826;branch=z9hG4bKPj9536a08e-1b7e-4f6e-8e97-fbbc3ddeb484
From: <sip:2@192.168.0.63>;tag=ec1b8fad-4389-4d8d-bf31-ad9642fd6732
To: <sip:2@192.168.0.63>;tag=c34KXKU9vy9DS
Call-ID: 01a0d3fe-d2b4-4de0-8963-c902898a1f73
CSeq: 43258 REGISTER
User-Agent: FreeSWITCH-mod_sofia/1.6.10+git~20160824T215404Z~726448d962~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
WWW-Authenticate: Digest realm="192.168.0.63", nonce="7c33266c-45bf-474b-bc67-98115d6a5627", algorithm=MD5, qop="auth"
Content-Length: 0


--end msg--
18:04:02.634   pjsua_core.c  ....TX 745 bytes Request msg REGISTER/cseq=43259 (tdta0x80de77000) to UDP 192.168.0.63:5060:
REGISTER sip:192.168.0.63 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.75:62826;rport;branch=z9hG4bKPj8605f6a8-93cd-47db-8f8d-f9dc8c1dee02
Max-Forwards: 70
From: <sip:2@192.168.0.63>;tag=ec1b8fad-4389-4d8d-bf31-ad9642fd6732
To: <sip:2@192.168.0.63>
Call-ID: 01a0d3fe-d2b4-4de0-8963-c902898a1f73
CSeq: 43259 REGISTER
Contact: <sip:2@192.168.0.75:62826;ob>
Expires: 200
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username="2", realm="192.168.0.63", nonce="7c33266c-45bf-474b-bc67-98115d6a5627", uri="sip:192.168.0.63", response="53e56675a6525ed6d7aed0388b3a6591", algorithm=MD5, cnonce="c9cdb101-8134-4e6a-b03b-eec257af77ff", qop=auth, nc=00000001
Content-Length:  0


--end msg--
18:04:02.636   pjsua_core.c  .RX 633 bytes Response msg 200/REGISTER/cseq=43259 (rdata0x80cf2e028) from UDP 192.168.0.63:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.75:62826;rport=62826;branch=z9hG4bKPj8605f6a8-93cd-47db-8f8d-f9dc8c1dee02
From: <sip:2@192.168.0.63>;tag=ec1b8fad-4389-4d8d-bf31-ad9642fd6732
To: <sip:2@192.168.0.63>;tag=DcycZecDt7Z0m
Call-ID: 01a0d3fe-d2b4-4de0-8963-c902898a1f73
CSeq: 43259 REGISTER
Contact: <sip:2@192.168.0.75:62826;ob>;expires=200
Date: Wed, 07 Sep 2016 13:04:02 GMT
User-Agent: FreeSWITCH-mod_sofia/1.6.10+git~20160824T215404Z~726448d962~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0


--end msg--
18:04:02.636    pjsua_acc.c  ....SIP outbound status for acc 0 is not active
18:04:02.636    pjsua_acc.c  ....sip:2@192.168.0.63: registration success, status=200 (OK), will re-register in 200 seconds
18:04:02.636    pjsua_acc.c  ....Keep-alive timer started for acc 0, destination:192.168.0.63:5060, interval:15s
18:04:02.728   pjsua_core.c  .RX 914 bytes Request msg NOTIFY/cseq=96290657 (rdata0x80cf2e028) from UDP 192.168.0.63:5060:
NOTIFY sip:2@192.168.0.75:62826;ob SIP/2.0
Via: SIP/2.0/UDP 192.168.0.63;rport;branch=z9hG4bKc2jKv8pXtD2SH
Max-Forwards: 70
From: <sip:2@192.168.0.63>;tag=eNQ509vgQgpKg
To: <sip:2@192.168.0.63>
Call-ID: 640d57c9-ef9e-1234-f5b6-902b3433882b
CSeq: 96290657 NOTIFY
Contact: <sip:mod_sofia@192.168.0.63:5060>
User-Agent: FreeSWITCH-mod_sofia/1.6.10+git~20160824T215404Z~726448d962~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Event: message-summary
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Subscription-State: terminated;reason=noresource
Content-Type: application/simple-message-summary
Content-Length: 61

Messages-Waiting: no
Message-Account: sip:2@192.168.0.63


--end msg--
18:04:02.728   pjsua_pres.c  .Got unsolicited NOTIFY from 192.168.0.63:5060..
18:04:02.728   pjsua_core.c  ...TX 297 bytes Response msg 200/NOTIFY/cseq=96290657 (tdta0x80e81f000) to UDP 192.168.0.63:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.63;rport=5060;received=192.168.0.63;branch=z9hG4bKc2jKv8pXtD2SH
Call-ID: 640d57c9-ef9e-1234-f5b6-902b3433882b
From: <sip:2@192.168.0.63>;tag=eNQ509vgQgpKg
To: <sip:2@192.168.0.63>;tag=z9hG4bKc2jKv8pXtD2SH
CSeq: 96290657 NOTIFY
Content-Length:  0


--end msg--
Startup dlg  finished
[========= в этом месте программа ждет 25 секунд =======]
ESL Connected
 Window Icon setted
MainAppFrameWindow2 ctor
pLogViewWidget created
pSplitterSoundPlay created
Main Window created

comment:21 by dimag, 8 years ago

Очевидно программа зависает на следующей строке
ESLconnect.Connect(currentConfig.sCurrentHost, 0, "", currentConfig.seslPassword, "heartbeat PRESENCE_IN RELOADXML CHANNEL_CALLSTATE SERVER_DISCONNECTED CLIENT_DISCONNECTED BACKGROUND_JOB MODULE_LOAD CUSTOM sofia::register sofia::expire sofia::unregister conference::maintenance");
на функции esl_connect.
Почему у вас она выполняется 25 секунд, я не знаю.

in reply to:  21 comment:22 by alx, 8 years ago

Replying to dimag:

Почему у вас она выполняется 25 секунд, я не знаю.

25 секунд - это таймаут ожидания сервером аутентификации от клиента.

Last edited 8 years ago by alx (previous) (diff)

comment:23 by dimag, 8 years ago

Может это проблема FS?

in reply to:  23 comment:24 by alx, 8 years ago

Replying to dimag:

Может это проблема FS?

Перечитайте, пожалуйста, описание тикета. Там есть дамп соединения, из которого ясно видно, что клиент не отвечает серверу на запрос аутентификации. Каким образом это может быть проблемой сервера?

comment:25 by alx, 8 years ago

Проблема обнаружилась в функции handle_recv(), а именно, вот в этом фрагменте:

        if (!(activity = recv(handle->sock, data, datalen, 0))) {
            activity = -1;
        } else if (errno == EINTR || errno == EAGAIN || errno == EWOULDBLOCK) {
            activity = 0;
        }

Здесь второе условие проверялось в случае, если recv() возвратила не 0. Но errno устанавливается только в том случае, если возвращено -1. При возврате же положительного числа errno не должно было проверяться.

В другом (более позднем) варианте кода условие расширено таким образом:

    } else if (activity < 0 && (errno == EINTR || errno == EAGAIN || errno == EWOULDBLOCK)) {

Предлагаю, во избежание подобных ситуаций, а также учитывая, что libesl как самостоятельный продукт не существует, включить код libesl в наш репозиторий и собирать вместе с программой MC04-Dispatcher.

comment:26 by dimag, 8 years ago

Resolution: fixed
Status: newclosed

r455
В версии ESL, которую я использовал, был правильный фрагмент кода, совпадающей с приведённым вами фрагментом.
Добавил используемый код библиотеки ESL в svn, в решение. В программе далее будет использоваться библиотека ESL не из исходного кода библиотеки FreeSwitch, а из добавленной в решение библиотеке ESL.

Note: See TracTickets for help on using tickets.