#267 closed баг (готово)
Окончание FS Idle, а вызов от его имени продолжается
Reported by: | san | Owned by: | alx |
---|---|---|---|
Priority: | средний | Milestone: | 1 очередь |
Component: | VE-01 | Keywords: | |
Cc: |
Description (last modified by )
Несколько окончаний FS в плате VE-01 настроены на вызов по "горячей линии" номера 400 (вызов уходит в PRI).
Во время эксперимента трубки телефонов, соответствующих окончаниям FS поднимались в произвольном порядке, в том числе и одновременно.
Спустя некоторое время вызов от одного из FS продолжал отображаться в PRI, а телефон соответствующий номеру вызываемого звонил, при этом само вызывающее окончание имело статус Idle.
Прилагаю лог платы VE-01 и конфиг блока.
r41
Attachments (8)
Change History (19)
by , 6 years ago
by , 6 years ago
Attachment: | config.xml added |
---|
by , 6 years ago
Attachment: | messages.zip added |
---|
comment:1 by , 6 years ago
Description: | modified (diff) |
---|
comment:3 by , 6 years ago
Выявить вторую из названных причин, очевидно, можно обновлением страницы в браузере. Если после обновления страницы состояние начинает отображаться верно, то проблема в скрипте браузера.
comment:4 by , 6 years ago
Хм... Только что я заметил некоторое несоответствие: согласно логу (см. приведенную в comment:2 строчку), вызов от абонента 161 был направлен в таймслот 19 транка PRI. На скриншоте же в состоянии Proceeding находится канал 110, что соответствует таймслоту 13 транка PRI...
Как это объяснить? Скриншот не соответствует логу? Или после получения бага абонент 161 продолжал делать вызовы?
comment:5 by , 6 years ago
Resolution: | → готово |
---|---|
Status: | new → closed |
Повторный просмотр лога показал следующее:
- абонент 161 снимает трубку и делает вызов номера 400;
- окончание PRI прниимает вызов, занимает таймслот 13 и отправляет SETUP;
- от удаленной стороны (таймслот 13) приходит сообщение CALL PROCEEDING;
- от удаленной стороны (таймслот 13) приходит сообщение ALERTING;
- абонент 161 размыкает шлейф;
- абонент 161 (все еще находясь в состоянии Calling, так как таймер отбоя еще не сработал) замыкает шлейф. Происходит новый вызов номера 400.
- окончание PRI принимает вызов, занимает таймслот 14 и отправляет SETUP;
- от удаленной стороны (таймслот 14) приходит сообщение CALL PROCEEDING;
- от удаленной стороны (таймслот 14) приходит сообщение DISCONNECT;
- от удаленной стороны (таймслот 14) приходит сообщение RELEASE COMPLETE;
В данной последовательности событий ошибкой является то, что сделан новый вызов номера 400. Проблема уже исправлена в r1405 добавлением проверки, находится ли канальное окончание в состоянии Calling.
follow-up: 7 comment:6 by , 6 years ago
Resolution: | готово |
---|---|
Status: | closed → reopened |
При повторе эксперимента c прошивкой ревизии 42, баг воспроизвёлся в несколько другой форме:
Вызов в PRI остался, но в поле вызывающий пусто
Экперимент 1:
А во втором эксперименте воспроизвёлся как описано в тикете
Экперимент 2:
Прилагаю логи обоих экспериментов и новый конфиг файл блока(немного отличается от приложенного ранее)
by , 6 years ago
by , 6 years ago
by , 6 years ago
Attachment: | messages_1 added |
---|
by , 6 years ago
Attachment: | messages_2.zip added |
---|
by , 6 years ago
Attachment: | config_new.xml added |
---|
follow-up: 8 comment:7 by , 6 years ago
Replying to san:
При повторе эксперимента c прошивкой ревизии 42, баг воспроизвёлся в несколько другой форме:
По поводу первого эксперимента: "баг воспроизвелся в другой форме", очевидно, означает, что воспроизвелся другой баг. А раз так, то следует открыть новый тикет, а не переоткрывать тикет уже исправленного бага. Повторю еще раз: описанный в данном тикете баг заключался в том, что при поднятии трубки (и соблюдении ряда других условий) канальное окончание FXS выполняло новый исходящий вызов, не сняв сделанный ранее. После исправления r1405 описанная ситуация невозможна, так как в описанном случае новый вызов просто не выполняется.
По поводу второго эксперимента: я не нашел в приложенных логах прием вызова каналом 157 (ts=156). Саша, уточни, пожалуйста, точное время вызова.
follow-up: 10 comment:8 by , 6 years ago
"баг воспроизвелся в другой форме", очевидно, означает, что воспроизвелся другой баг
Визуальные отличия небольшие, к тому-же во втором эксперименте на вид разницы с описанным в тикете нет.
Саша, уточни, пожалуйста, точное время вызова
к сожалению не могу уточнить, т.к.
Во время эксперимента трубки телефонов, соответствующих окончаниям FS поднимались в произвольном порядке, в том числе и одновременно.
я предполагал что именно в логе всё и зафиксируется
follow-up: 11 comment:9 by , 6 years ago
а ближе к концу лога разве это не оно ?
May 23 07:52:36 sip_ua[363]: user_agent.cpp:3099: --> ua_dial_out() <sip:129@192.168.0.95> -> sip:400@192.168.0.95 ()... May 23 07:52:36 sip_ua[476]: repro.cpp:435: doSessionAccounting(): Session Created 'branch=z9hG4bK1914529745' May 23 07:52:36 sip_ua[387]: user_agent.cpp:1987: INVITE received: sip:400@127.0.0.1:6060;transport=udp (Call-ID: 1208025391@(null)) ... ... ... May 23 07:52:37 sip_ua[363]: pri.cpp:582: ---> PRI[144]: Incoming call, ts=-1, flags=0002, data=88 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > DL-DATA request May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > Protocol Discriminator: Q.931 (8) len=29 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > TEI=0 Call Ref: len= 2 (reference 25/0x19) (Sent from originator) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > Message Type: SETUP (5) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > Protocol Discriminator: Q.931 (8) len=29 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > TEI=0 Call Ref: len= 2 (reference 25/0x19) (Sent from originator) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > Message Type: SETUP (5) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: > [04 03 80 90 a3] May 23 07:52:37 sip_ua[363]: user_agent.cpp:3484: Call 88 routed to TS 156 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Protocol Discriminator: Q.931 (8) len=10 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < TEI=0 Call Ref: len= 2 (reference 25/0x19) (Sent to originator) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Message Type: CALL PROCEEDING (2) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < [18 03 a9 83 9c] May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit Other(PRI) Spare: 0 Exclusive Dchan: 0 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < ChanSel: As indicated in following octets May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Ext: 1 Channel: 28 Type: CPE] May 23 07:52:37 sip_ua[363]: pri.cpp:200: --> PRI[144]: PRI event: PRI_EVENT_PROCEEDING May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Protocol Discriminator: Q.931 (8) len=9 May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < TEI=0 Call Ref: len= 2 (reference 25/0x19) (Sent to originator) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Message Type: ALERTING (1) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < [1e 02 81 88] May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) May 23 07:52:37 sip_ua[363]: pri.cpp:544: PRI[144]: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] May 23 07:52:37 sip_ua[363]: pri.cpp:200: --> PRI[144]: PRI event: PRI_EVENT_RINGING May 23 07:52:37 sip_ua[363]: comcerto.cpp:6606: --> ts 156: 192.168.0.95[10312] --> 192.168.0.95[10058] May 23 07:52:37 sip_ua[363]: comcerto.cpp:6607: --> ts 156: codec PCMA, VAD is on May 23 07:52:37 sip_ua[363]: comcerto.cpp:6608: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98 May 23 07:52:37 sip_ua[363]: comcerto.cpp:6661: ts 156: calling createConnection() May 23 07:52:37 sip_ua[363]: comcerto.cpp:6723: ts 156: starting RTP stream to 02:ad:c3:00:00:e0 May 23 07:52:37 sip_ua[387]: user_agent.cpp:2132: ---> ringing with status code 180 May 23 07:52:37 sip_ua[363]: fxs.cpp:419: ---> ts=29, state=Calling: RTP parameters, ts=29, flags=0000, data=87 May 23 07:52:37 sip_ua[363]: comcerto.cpp:6606: --> ts 29: 192.168.0.95[10058] --> 192.168.0.95[10312] May 23 07:52:37 sip_ua[363]: comcerto.cpp:6607: --> ts 29: codec PCMA, VAD is on May 23 07:52:37 sip_ua[363]: comcerto.cpp:6608: --> audio pt: 8/8, event pt: 101/101, VBD pt: 98/98 May 23 07:52:37 sip_ua[363]: comcerto.cpp:6723: ts 29: starting RTP stream to 02:ad:c3:00:00:e0 May 23 07:52:37 sip_ua[363]: fxs.cpp:419: ---> ts=29, state=Calling: Remote is ringing, ts=29, flags=0000, data=87
comment:10 by , 6 years ago
Replying to san:
"баг воспроизвелся в другой форме", очевидно, означает, что воспроизвелся другой баг
Визуальные отличия небольшие, к тому-же во втором эксперименте на вид разницы с описанным в тикете нет.
Хорошо, посмотрим лог детальнее. В логах есть два случая вызова, принятого каналом 130. Случай первый:
- May 23 07:44:04 со стороны IP принят INVITE, удаленной стороне передано сообщение SETUP.
- В ответ на SETUP от удаленной стороны получено CALL PROCEEDING.
- От удаленной стороны получено ALERTING. В этот момент шлюз попытался создать соединение, но получил от MSP сообщение об ошибке:
May 23 07:44:04 sip_ua[363]: comcerto.cpp:2165: !!!!! function SUPVSR_CREATE_CHANNEL (0x0010): error ERR_TDMDRV_INVTS (0xffbd): May 23 07:44:04 sip_ua[363]: comcerto.cpp:2166: TDM timeslot is invalid May 23 07:44:04 sip_ua[363]: comcerto.cpp:3053: createConnection() failed (result=-65469) May 23 07:44:04 sip_ua[363]: comcerto.cpp:6664: ts 129: createConnection() failed (result=-1)
Подобной ошибки не возникало в ходе вызова, о котором говорится в описании тикета. Следовательно, имел место другой баг, а не повторение описанного в тикете.
Случай второй:
- May 23 07:51:53 со стороны IP принят INVITE, передано сообщение SETUP.
- В ответ на SETUP от удаленной стороны получено CALL PROCEEDING.
- May 23 07:51:54 от удаленной стороны получено ALERTING.
- May 23 07:51:54 со стороны IP принято CANCEL.
- Удаленной стороне отправлено DISCONNECT.
- От удаленной стороны получено RELEASE.
- Удаленной стороне передано RELEASE COMPLETE.
Как видно далее в May 23 07:51:58, канал 130 (ts=129) находится в состоянии Idle. Таким образом, вызов завершился нормально, описанный баг не имел места.
comment:11 by , 6 years ago
Resolution: | → готово |
---|---|
Status: | reopened → closed |
Replying to san:
а ближе к концу лога разве это не оно ?
В процитированном фрагменте лога я вижу отправку SETUP, привязанную к таймслоту 25 внутри PRI (reference 25/0x19
), что соответствует таймслоту 153 (128 + 25) платы VE-01 или каналу 154 (153 + 1). На скриншоте же в состоянии Proceeding находится канал 157, а не 154.
Таймслот 156 в логе, действительно, фигурирует, но все, что нам говорит лог - это что для таймслота 156 был создан RTP поток. Более в логе этот таймслот не упоминается.
Таким образом, свидетельств повторения описанного в тикете бага в прошивке 42 я не вижу. Мне не остается ничего кроме как снова закрыть тикет...
После опускания трубки был послан RELEASE, после чего в ответ был получен RELEASE COMPLETE.
После чего в логе присутствует запись
После вывода этой записи каналу присваивается состояние Idle (не вижу в коде возхможности этого избежать).
Предварительный вывод: канал перешел в состояние Idle, однако в окне браузера это не было отражено. Возможных причин я вижу две:
Надо придумать специальный эксперимент для установления места возникновения проблемы.