Проблема с факсами ooh323+res_fax+spandsp

starterx · Сообщение **starterx** » 20 янв 2014, 11:14

Добрый день всем.

Пытаюсь сейчас развернуть астер в качестве PBX/Callswitch и столкнулся проблемой отправки факсов через chan_ooh323.
Внешнюю телефонию сейчас получаю по h323+T.38. На данный момент для маршрутизации вызовов использую связку mera+siphit, которая уже сильно устарела, да и сипхит частенько подвисает. Плюс периодически имею проблемы с ходимостью факсов. Хочу убрать железные факсы в своей сети как класс и сделать факс-машину на астере.

Эксперименты провожу в связке с квинтумом DX2060, но пробовал и с аплинком - результат тот же.
Проблема заключается в следующем - при отправке факсов через SendFAX звонок рвется по RTPtimeout из ooh323.conf, но при этом сессия T38 устанавливается и идет передача факса. После разрыва звонка остаются открытыми(подвисшими) 2 UDP-сокета открытых для RTPmedia и астер исправно по ним шлет RTCP пакеты, хотя сессия уже завершена.
При увеличении RTP Timeout - T38 сессия проходит полностью и факс передается, звонок завершается нормально, но 2 UDP-сокета все равно остаются зависшими и в снифе видно отправку RTCP в адрес оригинатора.

Пробовал перебирать все настройки из ooh323.conf, rtp.conf, udptl.conf - никак не влияет на результат.
Пробовал на нескольких бренчах 11 версии, собирал 10.9 и последний trunk из SVN - везде эта бага проявляется.
Правда на 10.9 udp-сокеты всегда закрываются корректно по окончании звонка.

помогите разобраться. Что еще можно покрутить и попробовать ?
Репорт на issue.asterisk.org пока не выкладывал.

Ниже привожу консольный вывод и конфиги.
Сниф и debug h323 могу выложить по требованию.
дебаг факса почему то fax set debug on не выводится.

-- Attempting call on OOH323/DX2060/115 for faxout@faxsend:1 (Retry 1)
== Using ooh323-rtp TOS bits 16
> 0x7f40d40156a0 -- Probation passed - setting RTP source address to 10.50.67.148:10266
> Channel OOH323/DX2060-0 was answered
-- Executing [faxout@faxsend:1] Set("OOH323/DX2060-0", "FAXOPT(headerinfo)=Received by bla-bla") in new stack
-- Executing [faxout@faxsend:2] Set("OOH323/DX2060-0", "FAXOPT(localstationid)=Name") in new stack
-- Executing [faxout@faxsend:3] Set("OOH323/DX2060-0", "FAXOPT(maxrate)=14400") in new stack
-- Executing [faxout@faxsend:4] Set("OOH323/DX2060-0", "FAXOPT(minrate)=2400") in new stack
-- Executing [faxout@faxsend:5] Set("OOH323/DX2060-0", "FAXOPT(gateway)=no") in new stack
-- Executing [faxout@faxsend:6] Set("OOH323/DX2060-0", "FAXOPT(ecm)=yes") in new stack

some NoOp skipped here

-- Executing [faxout@faxsend:15] SendFAX("OOH323/DX2060-0", "/tmp/test.tiff,dsfz") in new stack
-- Channel 'OOH323/DX2060-0' sending FAX:
-- /tmp/test.tiff
[Jan 18 20:35:04] NOTICE[17946]: chan_ooh323.c:3868 do_monitor: Disconnecting call 'OOH323/DX2060-0' for lack of RTP activity in 61 seconds
== Spawn extension (faxsend, faxout, 15) exited non-zero on 'OOH323/DX2060-0'
[Jan 18 20:35:04] ERROR[17962]: chan_ooh323.c:4805 close_udptl_connection: Channel has no owner
[Jan 18 20:35:04] NOTICE[17961]: pbx_spool.c:402 attempt_thread: Call completed to OOH323/DX2060/115

[root@ippbx2 asterisk]# netstat -ln (перед отправкой факса)

Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 0.0.0.0:53 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:1720 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:25 0.0.0.0:* LISTEN
tcp 0 0 :::53 :::* LISTEN
tcp 0 0 :::22 :::* LISTEN
tcp 0 0 ::1:25 :::* LISTEN
udp 0 0 0.0.0.0:4520 0.0.0.0:*
udp 0 0 0.0.0.0:53 0.0.0.0:*
udp 0 0 0.0.0.0:5060 0.0.0.0:*
udp 0 0 0.0.0.0:4569 0.0.0.0:*
udp 0 0 :::53 :::*

После отправки факса и завершения звонка

udp 0 0 0.0.0.0:15228 0.0.0.0:*
udp 784 0 0.0.0.0:15229 0.0.0.0:*
udp 0 0 0.0.0.0:4520 0.0.0.0:*
udp 0 0 0.0.0.0:53 0.0.0.0:*
udp 0 0 0.0.0.0:5060 0.0.0.0:*
udp 0 0 0.0.0.0:4569 0.0.0.0:*
udp 0 0 :::53 :::*

[root@ippbx2 asterisk]# tcpdump -nN net 10.50.67.144/29 -v (после завершения звонка)

tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
20:40:25.875092 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 72)
192.168.235.254.15229 > 10.50.67.148.10267: UDP, length 44
20:40:25.876192 IP (tos 0x0, ttl 63, id 5675, offset 0, flags [none], proto ICMP (1), length 56)
10.50.67.148 > 192.168.235.254: ICMP 10.50.67.148 udp port 10267 unreachable, length 36
IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 72)
192.168.235.254.15229 > 10.50.67.148.10267: UDP, length 44
20:40:30.875459 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 72)
192.168.235.254.15229 > 10.50.67.148.10267: UDP, length 44
20:40:30.876516 IP (tos 0x0, ttl 63, id 5676, offset 0, flags [none], proto ICMP (1), length 56)
10.50.67.148 > 192.168.235.254: ICMP 10.50.67.148 udp port 10267 unreachable, length 36
IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 72)
192.168.235.254.15229 > 10.50.67.148.10267: UDP, length 44

Увеличенный rtp timeout и успешное прохождение факса.

-- Attempting call on OOH323/DX2060/115 for faxout@faxsend:1 (Retry 1)
== Using ooh323-rtp TOS bits 16
> 0x7fce14015960 -- Probation passed - setting RTP source address to 10.50.67.148:10272
> Channel OOH323/DX2060-0 was answered
-- Executing [faxout@faxsend:1] Set("OOH323/DX2060-0", "FAXOPT(headerinfo)=Received by bla-bla") in new stack
-- Executing [faxout@faxsend:2] Set("OOH323/DX2060-0", "FAXOPT(localstationid)=Name") in new stack
-- Executing [faxout@faxsend:3] Set("OOH323/DX2060-0", "FAXOPT(maxrate)=14400") in new stack
-- Executing [faxout@faxsend:4] Set("OOH323/DX2060-0", "FAXOPT(minrate)=2400") in new stack
-- Executing [faxout@faxsend:5] Set("OOH323/DX2060-0", "FAXOPT(gateway)=no") in new stack
-- Executing [faxout@faxsend:6] Set("OOH323/DX2060-0", "FAXOPT(ecm)=yes") in new stack

some NoOp skipped here

-- Executing [faxout@faxsend:15] SendFAX("OOH323/DX2060-0", "/tmp/test.tiff,dsfz") in new stack
-- Channel 'OOH323/DX2060-0' sending FAX:
-- /tmp/test.tiff
-- Executing [faxout@faxsend:16] NoOp("OOH323/DX2060-0", "Error:") in new stack
-- Executing [faxout@faxsend:17] NoOp("OOH323/DX2060-0", "Filename:/tmp/test.tiff") in new stack
-- Executing [faxout@faxsend:18] NoOp("OOH323/DX2060-0", "Pages:1") in new stack
-- Executing [faxout@faxsend:19] NoOp("OOH323/DX2060-0", "Rate:14400") in new stack
-- Executing [faxout@faxsend:20] NoOp("OOH323/DX2060-0", "RemoteStationID:") in new stack
-- Executing [faxout@faxsend:21] NoOp("OOH323/DX2060-0", "Resolution:8031x7700") in new stack
-- Executing [faxout@faxsend:22] NoOp("OOH323/DX2060-0", "Status:SUCCESS") in new stack
-- Executing [faxout@faxsend:23] NoOp("OOH323/DX2060-0", "StatusString:OK") in new stack
-- Executing [faxout@faxsend:24] Hangup("OOH323/DX2060-0", "") in new stack
== Spawn extension (faxsend, faxout, 24) exited non-zero on 'OOH323/DX2060-0'
[Jan 18 21:08:46] NOTICE[18114]: pbx_spool.c:402 attempt_thread: Call completed to OOH323/DX2060/115

[root@ippbx2 asterisk]# netstat -ln (после звонка с большим rtp-таймаутом)

Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 0.0.0.0:53 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN
tcp 0 0 0.0.0.0:1720 0.0.0.0:* LISTEN
tcp 0 0 127.0.0.1:25 0.0.0.0:* LISTEN
tcp 0 0 :::53 :::* LISTEN
tcp 0 0 :::22 :::* LISTEN
tcp 0 0 ::1:25 :::* LISTEN
udp 0 0 0.0.0.0:4520 0.0.0.0:*
udp 0 0 0.0.0.0:53 0.0.0.0:*
udp 0 0 0.0.0.0:5060 0.0.0.0:*
udp 0 0 0.0.0.0:4569 0.0.0.0:*
udp 0 0 0.0.0.0:13022 0.0.0.0:*
udp 360 0 0.0.0.0:13023 0.0.0.0:*
udp 0 0 :::53 :::*

Конфиги и версии

CentOS 6.5 x64
[root@ippbx2 asterisk]# uname -srvmpio
Linux 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

ippbx2*CLI> core show version
Asterisk 11.2-cert3 built by root @ ippbx2.local on a x86_64 running Linux on 2014-01-18 14:48:11 UTC

ippbx2*CLI> ooh323 show config

Objective Open H.323 Channel Driver's Config:
IP:Port: 0.0.0.0:1720
H.225 port range: 12030-12230
FastStart yes
Tunneling yes
MediaWaitForConnect yes
DirectRTP no
EarlyDirectRTP no
H.323 LogFile: /var/log/asterisk/h323_log
Context: incoming
Capability: (alaw)
DTMF Mode: rfc2833
DTMF Codec: 101
T.38 Mode: faxgw/chan_sip compatible
FAX Detect: No
RoundTrip: 3,5

ippbx2*CLI> fax show capabilities

Registered FAX Technology Modules:

Type : Spandsp
Description : Spandsp FAX Driver
Capabilities : SEND RECEIVE T.38 G.711 GATEWAY

ippbx2*CLI> fax show version
FAX For Asterisk Components:
Applications: 11.2-cert3
Spandsp FAX Driver: 20110122 075024

ippbx2*CLI> ooh323 show peer DX2060
Name: DX2060
FastStart/H.245 Tunneling:yes,yes
DirectRTP no
EarlyDirectRTP no
Format Prefs: (alaw:20)
DTMF Mode: rfc2833
DTMF Codec: 101
T.38 Mode: faxgw/chan_sip compatible
FAX Detect: No
AccountCode: ast_h323
AMA flags: Unknown
IP:Port: 10.50.67.148:1720
OutgoingLimit: 0
rtptimeout: 60
nat: no

amateur · Сообщение **amateur** » 21 янв 2014, 11:40

Запишите трафик, посмотрим.

starterx · Сообщение **starterx** » 21 янв 2014, 13:05

Спасибо, за отзыв.

С вашего позволения отвечу ссылкой
https://issues.asterisk.org/jira/browse/ASTERISK-23166

Также приаттачил файлы логов с дебагом и tcpdump cap без фильтра.

amateur · Сообщение **amateur** » 21 янв 2014, 14:54

Сразу скажу, что я не разбираюсь в chan_ooh323, но попробую предложить быстрое решение.

Смотрю последнюю версию chan_ooh323.c в SVN branch/10.

Указанное в log сообщение формируется следующим фрагментом кода:

Код: Выделить всё

3717				if (h323->rtp && h323->owner && h323->rtptimeout &&
3718					h323->lastrtprx &&
3719					h323->lastrtprx + h323->rtptimeout < t) {
3720					if (!ast_channel_trylock(h323->owner)) {
3721						ast_softhangup_nolock(h323->owner, AST_SOFTHANGUP_DEV);
3722						ast_log(LOG_NOTICE, "Disconnecting call '%s' for lack of RTP activity in %ld seconds\n", h323->owner->name, (long) (t - h323->lastrtprx));
3723						ast_channel_unlock(h323->owner);
3724					}
3725					
3726				}

Соответственно, если в логическом выражении

Код: Выделить всё

h323->rtp && h323->owner && h323->rtptimeout && h323->lastrtprx && h323->lastrtprx + h323->rtptimeout < t

нарушить хотя бы одно условие, то весь последующий фрагмент кода выполняться не будет.

Согласно следующим строчкам, параметр h323->rtptimeout формируется из конфигурации chan_ooh323 (секция [general], параметр rtptimeout)

Код: Выделить всё

521		pvt->rtptimeout = gRTPTimeout;

и

Код: Выделить всё

2816			} else if (!strcasecmp(v->name, "rtptimeout")) {
2817				gRTPTimeout = atoi(v->value);
2818				if (gRTPTimeout <= 0)
2819					gRTPTimeout = 60;

Получается, что если установить

Код: Выделить всё

[general]
rtptimeout=0

проблема должна исчезнуть.

В чем причина такого поведения пока не разобрался. Предполагаю, что при закрытии логических каналов для передачи речи, и открытии логических каналов передачи факсимильных сообщений нужно прекращать проверку наличия RTP. Осталось понять откуда взять индикацию текущего состояния сеанса T.38

amateur · Сообщение **amateur** » 21 янв 2014, 15:15

В общем, напрашивается следующее изменение...

Код: Выделить всё

3717            if (h323->rtp && !h323->faxmode && h323->owner && h323->rtptimeout &&
3718               h323->lastrtprx &&
3719               h323->lastrtprx + h323->rtptimeout < t) {

may · Сообщение **may** » 21 янв 2014, 15:30

День добрый,

вообще по этой теме лучше завести issue на issues.asterisk.org.
Вроде как lastrx/tx выставляются и при udptl пакетах, буду проверять.
Зафиксить это несложно.

amateur · Сообщение **amateur** » 21 янв 2014, 15:44

Добрый. Да, я пожалуй поторопился... Меня смутило название lastrtprx. Думал, что это не относится к UDP TL.

Поискал в коде, действительно время устанавливается и для UDP TL (branch/10):

Код: Выделить всё

4608		case 5:
4609			f = ast_udptl_read(p->udptl);		/* UDPTL t.38 data */
4610			if (gH323Debug) {
4611				 ast_debug(1, "Got UDPTL %d/%d len %d for %s\n",
4612					f->frametype, f->subclass.integer, f->datalen, ast->name);
4613			}
4614			p->lastrtprx = time(NULL);
4615			break;

Причем, тут в записи трафика проблема именно в том, что после получения CFR от удаленной стороны Asterisk присылает v17-14400-short-training. Потом от удаленной стороны тишина 60 секунд (rtptimeout), и ReleaseComplete со стороны Asterisk.

starterx · Сообщение **starterx** » 21 янв 2014, 15:53

may писал(а):День добрый,

вообще по этой теме лучше завести issue на issues.asterisk.org.
Вроде как lastrx/tx выставляются и при udptl пакетах, буду проверять.
Зафиксить это несложно.

Уже сделано....
https://issues.asterisk.org/jira/browse/ASTERISK-23166

Из того что я понял - происходит путаница в номерах логических портов между RTP-media и T38.
И закрытия сокетов нету по окончании обработки звонка.

Но я в C-программинге не силен, а убивать кучу времени чтоб разобраться к сожалению нет возможности.

amateur · Сообщение **amateur** » 21 янв 2014, 16:00

Никакой путаницы в ooh323 не происходит. Проблема именно с обменом по T.38. Включите пожалуйста дополнительно отладку spandsp и покажите нам все записи в течение вызова.

starterx · Сообщение **starterx** » 21 янв 2014, 22:17

Комплект дебагов rtp,udptl,fax,ooh323+tcpdump и консоль.

Проблема с факсами ooh323+res_fax+spandsp

Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp

Re: Проблема с факсами ooh323+res_fax+spandsp