Столкнулись с проблемой в Asterisk 1.8 при auto-dial out.
Честно сказать не знаю то ли мы такие «везучие», то ли лыжи не едут, но в очередной раз мы наступаем на грабли о которых гугл и великий ALL толком ничего «сказать» не может. У всех все типа работает и если есть похожее, то оно решается путем чтения мануала до полного просветления.
Имеем:
- Virtualbox 4.0.12
- Freebsd 8.1-RELEASE
- Asterisk 1.8.17.0
В очередно раз появилась задача поднять Asterisk, нужно это для предоставления услуг IP-АТС для физиков.
Ранее мы ставили Asterisk 1.4, а тут решили что пора бы уже попробовать перейти на версию 1.8. Сказано — сделано.
Установка прошла как обычно, без проблем. После настройки, установки собственного web-интерфейса управления астериском и небольших изменений в виду некоторых отличий конфигов версии 1.8 от 1.4 мы приступили к тестированию.
Было обнаружено, что не работают функции callback, email2fax, web2fax. Все эти функции упираются в одну точку и имя ей auto-dial out, генерация call файлов для совершения автоматического исходящего вызова.
Начинаем разбираться. Запускаем астериск, заходим в консоль и включаем verbose:
# asterisk -r
aster*CLI> core set verbose 3
Verbosity is at least 3
Звоним на callback номер, где после проверки php скрипт генерит call-файл для совершения обратного вызова и отправляет его в /var/spool/asterisk/outgoing для непосредственно совершения вызова и зрим в консоль:
aster*CLI> [Oct 17 12:49:49] WARNING[35623]: pbx_spool.c:258 apply_outgoing: At least one of app or extension must be specified, along with tech and dest in file /var/spool/asterisk/outgoing/callback_1_813.call aster*CLI>
[Oct 17 12:49:49] WARNING[35623]: pbx_spool.c:419 scan_service: Invalid file contents in /var/spool/asterisk/outgoing/callback_1_813, deleting
Называется приехали… Сначала мы подумали что из-за разницы в версиях астера есть какое то отличие в синтаксисе call файла.
После прочтения auto-dial out заново стало понятно что это не так. Отличий нет. Хм….
Едем далее. Убираем из скрипта автоперемещение call файла в /var/spool/asterisk/outgoing и кладем его в созданную диру /var/spool/asterisk/outgoing-test и смотрим на результат генерации:
Channel: LOCAL/005@users_813_clientID_1
Callerid: 813
MaxRetries: 5
RetryTime: 15
WaitTime: 60
Context: callback_813_clientID_1
Extension: s
Priority: 1
Абсолютно нормальный call файл. Берем и копируем call файл руками:
# /bin/cp /tmp/aster/callback_1_813.call /var/spool/asterisk/outgoing/
И о чудо, астер уже не ругается в консоли и спокойно начинает обрабатывать файл и совершает исходящий вызов. Хм……
Тестим исходящий факс, где call файл уже генерится perl скриптом. Та же ситуёвина. При перемещении call файла в /var/spool/asterisk/outgoing скриптом в консоли астера идет ругань на call файл, а при копирования файла руками все ОК.
Хм….. снова приехали…..
Включаем дебаг:
aster*CLI> core set debug 9
Не помогает ничем, более детально проблема так и не описана. Чешем репу… гуглим… есть похожие случаи, но все равно не то что у нас.
Начинаем строить предположения:
а) Астер начинает обрабатывать call файл в соответствии с датой модификации файла (mtime). Проблема с touch (который сдвигает дату модификации call файла перед перемещением в outgoing) ?
б) проблема с правами на файл ?
Не буду подробно расписывать весь мозговой и ручной процесс, ибо это долго, а напишу вкратце.
Проверяем догадку «а»:
Смотрим какие у нас даты после создания call файла:
# stat /var/spool/asterisk/outgoing-test/callback_1_813.call
72 47370 -rw-r--r-- 1 asterisk asterisk 191847 238 "Oct 17 14:34:50 2012" "Oct 17 14:30:32 2012" "Oct 17 15:19:02 2012" "Oct 17 14:29:50 2012" 16384 4 0 callback_1_813.call
Даты перечисляются в таком порядке: a, m, c, B.
- a — access time, время последнего доступа к файлу
- m — modificatiom time, время последнего изменения файла
- c — create time, дата создания файла
- B — birth time of the inode, дата дескриптора
Как видно из вывода stat даты разные и сдвинуты во времени относительно СЕЙЧАС в будущее, напомню что это делается в скрипте генерации call файла командой touch.
Вывод: тут все ОК.
Проверяем догадку «б»:
какие права на файл не поставь, от какого юзера asterisk не запусти — результат тот же — в консоле астера:
At least one of app or extension must be specified, along with tech and dest in file
Мда…. asterisk запущенный от пользователя root не может прочитать файл с владельцем root или asterisk… это уже не в какие ворота….
Ну что ж, здравые идеи закончились и видимо без «напильника» уже не обойтись, т.к. проблему кроме нас самих никто не решит.
Лезем в исходки астера на предмет установления места где идет обработка call файла и его обработка. За обработку call файлов отвечает спулер:
/usr/ports/net/asterisk/work/asterisk-1.8.17.0/pbx/pbx_spool.c.
Открываем его для изучения с места где отпечатывается выше указанные ошибки при обработке call файла и смотрим строчки с номерами, которые печатаются в консоль в сообщении об ошибке: стр. 258 и стр. 419. Приходим к тому что без дебага того что же все же видит астер в call файле не обойтись. Добавляем:
ast_debug( 1, "[%s]: mode: %o, uid: %d, gid: %d, size: %ld, now: %ld, mtime: %ld, atime: %ld, ctime: %ld, birth: %ld\n", filename, st.st_mode, st.st_uid, st.st_gid, (long) st.st_size, (long) now, (long) st.st_mtime, (long) st.st_atime, (long) st.st_ctime, (long) st.st_birthtime );
Чтобы видеть права, пользователя, группу и даты. Запускаем скрипт генерации call файла и зрим в консоль:
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:517 queue_file: [/var/spool/asterisk/outgoing/callback_1_813.call]: mode: 100000, uid: 0, gid: 931, size: 0, now: 1350482288, mtime: 1350482288, atime: 1350482288, ctime: 1350482288, birth: 1350482288
Мда…. Размер файла ноль байт! О как ! Теперь понятно почему астер плюет ошибки при обработке файла, ведь он считает что файл ПУСТОЙ !
Так же смотрим man 2 stat на предмет значения mode и понимаем что права на файл (даже на чтение) отсутствуют у всех ! Так же видно что unixtime даты в полях now, mtime, atime, ctime, birth одинаковы и это текущая дата, а не даты, которые приведены выше в выводе stat /var/spool/asterisk/outgoing-test/callback_1_813.call копируемого файла.
Отсюда появляется догадка «в»:
При копировании call файла скриптом астер не дает файлу докопироваться и пускает его в обработку и анализу ДО того как он полностью перемещается в /var/spool/asterisk/outgoing.
Проверяем догадку «в»:
Ищем решение и оно нашлось достаточно быстро и достаточно тривиальное: «попросить» астер «заснуть» на 30 мс перед тем как хапать файл.
Делаем добавление в функции static void queue_file(const char *filename, time_t when) вызова usleep( 30000 ); перед if (stat(filename, &st)) { (в оригинальном исходном коде этот условный переход расположен в строке 484) и снова смотрим в консоль:
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:517 queue_file: [/var/spool/asterisk/outgoing/callback_1_813.call]: Data BEFORE usleep: mode: 100000, uid: 0, gid: 931, size: 0, now: 1350482288, mtime: 1350482288, atime: 1350482288, ctime: 1350482288, birth: 1350482288
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:532 queue_file: [/var/spool/asterisk/outgoing/callback_1_813.call]: Data AFTER usleep: mode: 100644, uid: 931, gid: 931, size: 153, now: 1350482288, mtime: 1350482298, atime: 1350482298, ctime: 1350482288, birth: 1350482288
Называется «почувствуйте разницу!».
Права и даты в строке выводимой после usleep уже правильные и соответствуют копируемому файлу.
И снова чудо ! Действительно этой задержки перед обработкой оказалось достаточно для завершения полного копирования call файла и он начал нормально обрабатываться asterisk`ом уже без ругани.
Вот такая вот история. Надеемся что кому нить поможет если он столкнется с похожей ситуёвиной.
Найти ответ на вопрос «Почему при копированием скриптом астер не дает файлу докопироваться, а при копировании руками все ОК ?» мы так и не сумели. Если у кого то есть предположения, то милости просим в комменты к статье.
Ну и напоследок:
Мы немного расширили режим отладки обработки call-файлов. Теперь при наложении нашего патча и указании вывода дебага (core set debug 1) будем видеть всю «историю процесса».
Пример:
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:765 scan_thread: Directory changed, rescan
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:517 queue_file: [/var/spool/asterisk/outgoing/callback_1_813.call]: Data BEFORE usleep: mode: 100000, uid: 0, gid: 931, size: 0, now: 1350482288, mtime: 1350482288, atime: 1350482288, ctime: 1350482288, birth: 1350482288
[Oct 17 17:58:08] DEBUG[2027]: pbx_spool.c:532 queue_file: [/var/spool/asterisk/outgoing/callback_1_813.call]: Data AFTER usleep: mode: 100644, uid: 931, gid: 931, size: 153, now: 1350482288, mtime: 1350482298, atime: 1350482298, ctime: 1350482288, birth: 1350482288
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:146 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: Fresh data: mode: 100644, uid: 931, gid: 931, size: 153, mtime: 1350482298, atime: 1350482298, ctime: 1350482288, birth: 1350482288
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:147 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: Read content
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 1: Channel: LOCAL/005@users_813_clientID_1
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 2: Callerid: 813
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 3: MaxRetries: 5
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 4: RetryTime: 15
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 5: WaitTime: 60
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 6: Context: callback_813_clientID_1
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 7: Extension: s
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:181 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: line 8: Priority: 1
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:277 apply_outgoing: [/var/spool/asterisk/outgoing/callback_1_813.call]: processed 8 lines
[Oct 17 17:58:18] DEBUG[2027]: pbx_spool.c:291 safe_append: Outgoing LOCAL/005@users_813_clientID_1: StartRetry
-- Attempting call on LOCAL/005@users_813_clientID_1 for s@callback_813_clientID_1:1 (Retry 1)
...
[Oct 17 17:58:23] NOTICE[2027]: pbx_spool.c:388 attempt_thread: Call completed to LOCAL/005@users_813_clientID_1
[Oct 17 17:58:23] DEBUG[2027]: pbx_spool.c:765 scan_thread: Directory changed, rescan
Т.е. теперь видны не только права и даты ДО и ПОСЛЕ, но и само содержимое call файла, которое хпнул asterisk.
Наш патч можно поместить прямо в порт /usr/ports/net/asterisk/files и пересобрать астер.
З.Ы. При копировании статьи ссылка на источник ОБЯЗАТЕЛЬНА !
Авторы: Панфилов Алексей (lehis (at) subnets.ru) и Николаев Дмитрий (virus (at) subnets.ru)
Загрузка...
Отправить на почту
