Окончание FS Idle, а вызов от его имени продолжается

[san]

Несколько окончаний FS в плате VE-01 настроены на вызов по "горячей линии" номера 400 (вызов уходит в PRI).
Во время эксперимента трубки телефонов, соответствующих окончаниям FS поднимались в произвольном порядке, в том числе и одновременно.
Спустя некоторое время вызов от одного из FS продолжал отображаться в PRI, а телефон соответствующий номеру вызываемого звонил, при этом само вызывающее окончание имело статус Idle.

Прилагаю лог платы VE-01 и конфиг блока.
r41

[alx]

После опускания трубки был послан RELEASE, после чего в ответ был получен RELEASE COMPLETE.
После чего в логе присутствует запись

May 17 05:33:26 sip_ua[363]: pri.cpp:503: --> channel=19, cause=Normal, unspecified

После вывода этой записи каналу присваивается состояние Idle (не вижу в коде возхможности этого избежать).

Предварительный вывод: канал перешел в состояние Idle, однако в окне браузера это не было отражено. Возможных причин я вижу две:

1. по какой-то причине (возможно, перегруженность служебной шины другими сообщениями?) сообщение об изменении состояния канала, отправленное платой VE-01, не было получено платой SW-01;
2. упомянутое выше сообщение платой SW-01 было получено, но отображаемое состояние не обновилось в результате какого-то бага в SW-01 и/или скрипте браузера.

Надо придумать специальный эксперимент для установления места возникновения проблемы.

[alx]

Выявить вторую из названных причин, очевидно, можно обновлением страницы в браузере. Если после обновления страницы состояние начинает отображаться верно, то проблема в скрипте браузера.

[alx]

Хм... Только что я заметил некоторое несоответствие: согласно логу (см. приведенную в comment:2 строчку), вызов от абонента 161 был направлен в таймслот 19 транка PRI. На скриншоте же в состоянии Proceeding находится канал 110, что соответствует таймслоту 13 транка PRI...

Как это объяснить? Скриншот не соответствует логу? Или после получения бага абонент 161 продолжал делать вызовы?

[alx]

Повторный просмотр лога показал следующее:

• абонент 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.

[san]

При повторе эксперимента c прошивкой ревизии 42, баг воспроизвёлся в несколько другой форме:
Вызов в PRI остался, но в поле вызывающий пусто
Экперимент 1:

А во втором эксперименте воспроизвёлся как описано в тикете
Экперимент 2:

Прилагаю логи обоих экспериментов и новый конфиг файл блока(немного отличается от приложенного ранее)

[alx]

Replying to san:

При повторе эксперимента c прошивкой ревизии 42, баг воспроизвёлся в несколько другой форме:

По поводу первого эксперимента: "баг воспроизвелся в другой форме", очевидно, означает, что воспроизвелся другой баг. А раз так, то следует открыть новый тикет, а не переоткрывать тикет уже исправленного бага. Повторю еще раз: описанный в данном тикете баг заключался в том, что при поднятии трубки (и соблюдении ряда других условий) канальное окончание FXS выполняло новый исходящий вызов, не сняв сделанный ранее. После исправления r1405 описанная ситуация невозможна, так как в описанном случае новый вызов просто не выполняется.

По поводу второго эксперимента: я не нашел в приложенных логах прием вызова каналом 157 (ts=156). Уточните, пожалуйста, точное время вызова.

[san]

"баг воспроизвелся в другой форме", очевидно, означает, что воспроизвелся другой баг

Визуальные отличия небольшие, к тому-же во втором эксперименте на вид разницы с описанным в тикете нет.

Саша, уточни, пожалуйста, точное время вызова

к сожалению не могу уточнить, т.к.

Во время эксперимента трубки телефонов, соответствующих окончаниям FS поднимались в произвольном порядке, в том числе и одновременно.

я предполагал что именно в логе всё и зафиксируется

[san]

а ближе к концу лога разве это не оно ?

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

[alx]

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. Таким образом, вызов завершился нормально, описанный баг не имел места.

[alx]

Replying to san:

а ближе к концу лога разве это не оно ?

В процитированном фрагменте лога я вижу отправку SETUP, привязанную к таймслоту 25 внутри PRI (reference 25/0x19), что соответствует таймслоту 153 (128 + 25) платы VE-01 или каналу 154 (153 + 1). На скриншоте же в состоянии Proceeding находится канал 157, а не 154.

Таймслот 156 в логе, действительно, фигурирует, но все, что нам говорит лог - это что для таймслота 156 был создан RTP поток. Более в логе этот таймслот не упоминается.

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