Subnets.ru blog

Channel Event Logging (CEL)

Дано:

• FreeBSD 8.1-RELEASE
• Asterisk 1.8.17.0

Полученные от CEL данные будем складывать в csv и MySQL.

MySQL CEL Backend:

Using MySQL for Channel Event records is supported by using ODBC and the cel_odbc module.

Ставим порты для ODBC

• /usr/ports/databases/unixODBC
• /usr/ports/databases/mysql-connector-odbc

# pkg_info | grep ODBC
mysql-connector-odbc-unixodbc-mysql55-5.1.9 ODBC driver for MySQL55 / unixodbc
unixODBC-2.3.1 ODBC library suite for Unix

# ls -la /usr/local/lib/libmyodbc*
-rwxr-xr-x 1 root wheel 260880 18 сен 09:21 /usr/local/lib/libmyodbc5.so

Смотрим расположение конфиг файлов:

# odbcinst -j

unixODBC 2.3.1
DRIVERS............: /usr/local/etc/odbcinst.ini
SYSTEM DATA SOURCES: /usr/local/etc/odbc.ini
FILE DATA SOURCES..: /usr/local/etc/ODBCDataSources
USER DATA SOURCES..: /root/.odbc.ini
SQLULEN Size.......: 4
SQLLEN Size........: 4
SQLSETPOSIROW Size.: 2

Правим /usr/local/etc/odbcinst.ini

[MySQL]
Description=ODBC for MySQL
Driver=/usr/local/lib/libmyodbc5.so
UsageCount=20001

Инсталим драйвер:

# odbcinst -i -d -f /usr/local/etc/odbcinst.ini

Правим /usr/local/etc/odbc.ini:

[mysql-odbc-ini-asterisk]
Driver=MySQL
SERVER=127.0.0.1
PORT=3306
DATABASE=asterisk
USER=asterisk
PASSWORD=password
OPTION=4194304

Проверяем список доступных DSN:

# odbcinst -s -q

[mysql-odbc-ini-asterisk]

Настраиваем конфиги в Asterisk

/usr/local/etc/asterisk/cel.conf:

[general]
enable=yes
;apps=dial,park
;events=APP_START,CHAN_START,CHAN_END,ANSWER,HANGUP,BRIDGE_START,BRIDGE_END
apps=all
events=all
dateformat = %F %T

[manager]
enabled=no

[radius]

В /usr/local/etc/asterisk/cel_custom.conf раскомментируем секцию [mappings].
Проверим наличие директории /var/log/asterisk/cel-custom, если её нет то создадим ей и не забываем установить необходимые права, чтобы asterisk смог осуществить запись.

/usr/local/etc/asterisk/res_odbc.conf:
[asterisk-res-odbc]
enabled => yes
dsn => mysql-odbc-ini-asterisk
username => asterisk
password => password
pre-connect => yes

/usr/local/etc/asterisk/cel_odbc.conf:
[first]
connection=asterisk-res-odbc
table=cel
loguniqueid=yes

Создаем таблицу в базе:

CREATE TABLE IF NOT EXISTS `cel` (
  `id` int(11) NOT NULL auto_increment,
  `eventtype` varchar(30) NOT NULL,
  `eventtime` datetime NOT NULL,
  `cid_name` varchar(80) NOT NULL,
  `cid_num` varchar(80) NOT NULL,
  `cid_ani` varchar(80) NOT NULL,
  `cid_rdnis` varchar(80) NOT NULL,
  `cid_dnid` varchar(80) NOT NULL,
  `exten` varchar(80) NOT NULL,
  `context` varchar(80) NOT NULL,
  `channame` varchar(80) NOT NULL,
  `src` varchar(80) NOT NULL,
  `dst` varchar(80) NOT NULL,
  `channel` varchar(80) NOT NULL,
  `dstchannel` varchar(80) NOT NULL,
  `appname` varchar(80) NOT NULL,
  `appdata` varchar(80) NOT NULL,
  `amaflags` int(11) NOT NULL,
  `accountcode` varchar(20) NOT NULL,
  `uniqueid` varchar(32) NOT NULL,
  `linkedid` varchar(32) NOT NULL,
  `peer` varchar(80) NOT NULL,
  `userdeftype` varchar(255) NOT NULL,
  `eventextra` varchar(255) NOT NULL,
  `userfield` varchar(255) NOT NULL,
  PRIMARY KEY  (`id`),
  KEY `uniqueid_index` (`uniqueid`),
  KEY `linkedid_index` (`linkedid`)
);

Перезапускаем:
# asterisk -r
asterisk*CLI> module reload res_odbc.so
— Reloading module ‘res_odbc.so’ (ODBC resource)
== Parsing ‘/usr/local/etc/asterisk/res_odbc.conf’: == Found
[Sep 18 10:05:59] NOTICE[84181]: res_odbc.c:1531 odbc_obj_connect: Connecting asterisk-res-odbc
[Sep 18 10:05:59] NOTICE[84181]: res_odbc.c:1563 odbc_obj_connect: res_odbc: Connected to asterisk-res-odbc [mysql-odbc-ini-asterisk]
[Sep 18 10:05:59] NOTICE[84181]: res_odbc.c:920 load_odbc_config: Registered ODBC class ‘asterisk-res-odbc’ dsn->[mysql-odbc-ini-asterisk]
[Sep 18 10:05:59] DEBUG[84181]: res_odbc.c:1504 odbc_obj_disconnect: Database handle 0x2a9a6000 deallocated

asterisk*CLI> module reload cel_odbc.so
— Reloading module ‘cel_odbc.so’ (ODBC CEL backend)
== Parsing ‘/usr/local/etc/asterisk/cel_odbc.conf’: == Found
— Found CEL table cel@asterisk-res-odbc.

asterisk*CLI> module reload cel_custom.so
— Reloading module ‘cel_custom.so’ (Customizable Comma Separated Values CEL Backend)
== Parsing ‘/usr/local/etc/asterisk/cel_custom.conf’: == Found

Проверяем:
asterisk*CLI> cel show status
CEL Logging: Enabled
CEL Tracking Event: ALL
CEL Tracking Event: CHAN_START
CEL Tracking Event: CHAN_END
CEL Tracking Event: HANGUP
CEL Tracking Event: ANSWER
CEL Tracking Event: APP_START
CEL Tracking Event: APP_END
CEL Tracking Event: BRIDGE_START
CEL Tracking Event: BRIDGE_END
CEL Tracking Event: CONF_START
CEL Tracking Event: CONF_END
CEL Tracking Event: PARK_START
CEL Tracking Event: PARK_END
CEL Tracking Event: BLINDTRANSFER
CEL Tracking Event: ATTENDEDTRANSFER
CEL Tracking Event: TRANSFER
CEL Tracking Event: HOOKFLASH
CEL Tracking Event: 3WAY_START
CEL Tracking Event: 3WAY_END
CEL Tracking Event: CONF_ENTER
CEL Tracking Event: CONF_EXIT
CEL Tracking Event: USER_DEFINED
CEL Tracking Event: LINKEDID_END
CEL Tracking Event: BRIDGE_UPDATE
CEL Tracking Event: PICKUP
CEL Tracking Event: FORWARD
CEL Tracking Application: all
CEL Event Subscriber: ODBC CEL backend
CEL Event Subscriber: CEL Custom CSV Logging

asterisk*CLI> odbc show

ODBC DSN Settings
——————

Name: asterisk-res-odbc
DSN: mysql-odbc-ini-asterisk
Last connection attempt: 1970-01-01 03:00:00
Pooled: No
Connected: Yes

После чего при прохождении вызовов должна будет заполняться таблица cel в БД asteriskб так же файл /var/log/asterisk/cel-custom/Master.csv.

Описание: CEL Events and Fields

Существует возможность генерить свои event`ы: CELGenUserEvent Application:

asterisk*CLI> core show application CELGenUserEvent

  -= Info about application 'CELGenUserEvent' =-

[Synopsis]
Generates a CEL User Defined Event.

[Description]
A CEL event will be immediately generated by this channel, with the supplied
name for a type.

[Syntax]
CELGenUserEvent(event-name[,extra])

[Arguments]
extra
    Extra text to be included with the event.

Ссылки:

• Channel Event Logging (CEL)
• Setting up Channel Event Logging (CEL) on Asterisk 1.8 or up with MySQL
• Asterisk™: The Definitive Guide: Chapter 24. System Monitoring and Logging
• Using MySQL through ODBC on FreeBSD

З.Ы. При копировании статьи ссылка на источник ОБЯЗАТЕЛЬНА !

Автор:  Николаев Дмитрий (virus (at) subnets.ru

Предыстория такова, что 19.08.2013 я нас своей рабочей машине FreeBSD 8.4-PRERELEASE (32х битка) делаю:

# portsnap fecth update && portupgrade -a

Придя на следующий день на работу и выполняя привычную команду:

# startx

Вместо иксов с enlightenment я получаю черный экран и усё…. приплыли.  На клаву вообще никак не реагирует.. ни свернуть исксы, ни убить иксы не пашет… Пришлось зайти с другой машины по SSH и прибить процесс enlightenment_start руками. Тогда черный экран пропадает и возвращается в консоль.

Просмотр лога /var/log/Xorg.0.log ничего не дает, т.к. ошибок (EE) там никаких нет и ничего даже смутно не указывает на какую либо проблему.

Посмотрев что именно обновлялось стало понятно что апдейтились дрова nvidia и сам enlightenment . Пробовал откатить дрова nvidia, перебрал несколько версий, но тщетно — черный экран и ничего более.

Затем пробовал стартануть исксы без конфига, т.е. сносил /etc/X11/xorg.conf как класс, но результат тот же — черный экран и ничего.  Затем попробовал стартануть иксы с автосгенеренным конфигом:

# Xorg :1 -configure

# X -config /root/xorg.conf.new

История та же — ошибок нет, наблюдаем черный экран. Гуглил.. либо ничего, либо не помогает, либо без решения.

В очередной раз выполнив в google.ru запрос поиска по: startx blank screen freebsd

Нашел только что можно добавить опцию -retro:

# X -config /root/xorg.conf.new -retro

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

После этого пришла мысль попробовать стартануть иксы без window manager`а вообще, тупо только с xterm:

# startx `which xterm`

Все ОК, никаких черных экранов, иксы стартуют, xterm нормально открывается. Такссс. Теперь пробуем самый простенький window manager, который идет с иксами по дефолту:

/usr/local/bin/twm (в портах лежит тут: /usr/ports/x11-wm/twm)

Редактируем /root/.xinitrc, ремим запуск enlightenment и добавляем запуск twm с xterm:

#exec /usr/local/bin/enlightenment_start
xterm &
exec /usr/local/bin/twm

Стартуем иксы и снова все хорошо — twm работает, xterm открылся. До кучи попробовал ещё один простенький wm /usr/ports/x11-wm/fvwm — результат тот же — все работает.

Ну тут, как говорится «К бабке не ходи», все понятно, проблема в самом enlightenment . Открываю xterm и пробую стартануть enlightenment руками оттуда, получаем последней строкой:

/usr/local/lib/enlightenment/utils/enlightenment_init ‘/usr/local/share/enlightenment/data/themes/default.edj’ ‘0’ ‘Enlightenment’ ‘0.17.4’

и все… ничего не происходит… Далее я делал кучу всякой всячины, которую не буду описывать т.к. ничего не помогало. В итоге я пришел к выводу о downgrade enlightenment  с 0.17.4 обратно на 0.17.3, т.к. с этой версией проблем не было.

Сказано — сделано. Ставим /usr/ports/ports-mgmt/portdowngrade и приступаем.

Просто даунгрейд порта /usr/ports/x11-xm/enlightenment ничего не дал… черный экран остался. Становится понятно, что придется даунгрейдить и его зависимости…

Ищем зависимости enlightenment и составляем полный список портов на downgrade согласно зависимостям одного порта от другого.

Делал я это с помощью команды:

# pkg_info -r enlightenment-0.17.3,2 | grep «: e»

А затем до кучи проверил тупо по версии:

# pkg_info | grep 1.7.8

Пройдясь по всем портам из составленного списка командой:

# pkg_info -R FULL_INSTALLED_PORT_NAME

Я расставил порты на downgrade в таком порядке исходя из их зависимостей:

• 1. ecore-ipc-1.7.8 devel/ecore-ipc
• 2.  ecore-sdl-1.7.8 graphics/ecore-sdl
• 3.  edje-1.7.8,2 graphics/edje
• 4. evas-loader-png-1.7.8 graphics/evas-loader-png
• 5. evas-loader-jpeg-1.7.8 graphics/evas-loader-jpeg
• 6. evas-loader-eet-1.7.8 graphics/evas-loader-eet
• 7. embryo-1.7.8,2 lang/embryo
• 8. eio-1.7.8 devel/eio
• 9. efreet-1.7.8 x11/efreet
• 10. e_dbus-1.7.8,1 devel/e_dbus
• 11. ecore-evas-1.7.8 graphics/ecore-evas
• 12. ecore-imf_evas-1.7.8 x11/ecore-imf_evas
• 13.   ecore-input_evas-1.7.8 x11/ecore-input_evas
• 14.  ecore-file-1.7.8 devel/ecore-file
• 15.  ecore-con-1.7.8 net/ecore-con
• 16.  ecore-imf-1.7.8 x11/ecore-imf
• 17.  ecore-x11-1.7.8 x11/ecore-x11
• 18.  ecore-input-1.7.8 x11/ecore-input
• 19.  ecore-main-1.7.8 devel/ecore-main
• 20. evas-engine-x11-1.7.8 graphics/evas-engine-buffer
• 21.  evas-engine-opengl-1.7.8 graphics/evas-engine-opengl
• 22.  evas-engine-buffer-1.7.8 graphics/evas-engine-buffer
• 23.  evas-core-1.7.8 graphics/evas-core
• 24.  eet-1.7.8,2 devel/eet
• 25.  eina-1.7.8 devel/eina
• 26. enlightenment x11-wm/enlightenment

Приступаем к downgrade:

# mkdir /usr/downgrade

# cd /usr/downgrade

# portdowngrade x11-wm/enlightenment | more

Смотрим до какой ревизии откатываемся:

------------------------------------------------------------------------
r318442 | gblach | 2013-05-18 23:36:31 +0400 (Sat, 18 May 2013) | 5 lines

- Update EFL libraries to 1.7.7
- Update Enlightenment to 0.17.3

Approved by: crees (mentor)

Вот r318442 то что нам и надо.

Выполняем с названием каждого порта из составленного списка команду portdowngrade ИМЯ_ПОРТА r318442, пример :

# portdowngrade x11-wm/enlightenment r318442

Затем я отмувил даунгрейднутые порты из папки /usr/downgrade на их законные места в папке /usr/ports, т.к. например ecore-sdl при сборке лазает в папку с портом ../../devel/ecore-main.

Теперь начинаем пересбор всех этих портов. Сначала удаляем установленный порт, затем собираем по новой, но уже даунгрейднутый.

Пример:

# pkg_delete -f ecore-ipc-1.7.8

# cd /usr/ports/devel/ecore-ipc

# make; make install

И так с каждым портом из списка. В итоге мы получаем:

# pkg_info | grep enli
enlightenment-0.17.3,2 A very artistic X window manager

Стартуем startx и все СНОВА РАБОТАЕТ !!! УРА !!!!

З.Ы. При копировании статьи ссылка на источник ОБЯЗАТЕЛЬНА !

Авторы:  Панфилов Алексей (lehis (at) subnets.ru) и Николаев Дмитрий (virus (at) subnets.ru)

Столкнулись с проблемой в 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)

З.Ы. При копировании статьи ссылка на источник ОБЯЗАТЕЛЬНА ! Пожалуйста, уважайте чужой труд.

Автор:  Панфилов Алексей (lehis (at) subnets.ru)

В продолжении статьи PPPoE сервер на встроенном в FreeBSD демоне pppoed рассмотрим ситуацию с LCP и LQR.

Немного теории:

LCP — сокращение от Link Control Protocol — протокол управления соединением.

LCP является частью протокола Point-to-Point.
При установлении соединения PPP передающее и принимающее устройство обмениваются пакетами LCP для уточнения специфической информации, которая потребуется при передаче данных.
Согласование параметров соединения проводится в форме переговоров.
LCP протокол осуществляет:

• проверку идентификации соединяемых устройств и, вследствие этого разрешает или отклоняет установку соединения
• определение приемлемого размера кадров для передачи MTU и приёма — MRU
• ограничение по ширине канала
• шифрование аутентификации соединения
• сжатие данных
• обнаружение петель маршрутизации
• проверку синтаксиса и поиск ошибок в конфигурации
• разрыв соединения, если какое-либо значение превышает заданный параметр

Устройства не могут передавать данные друг другу по сети прежде чем LCP пакеты не определят доступность устанавливаемого соединения.

LQR — Link Quality Report так же является частью протокола Point-to-Point и нужен для оценки состояния и качества связи PPP.

Если вы используете демон pppoed под FreeBSD, то в логах /var/log/ppp.log вам могут встречаться такие строки:

Apr 5 12:16:41 vpn-01 ppp[3951]: tun1: Warning: lqr_RecvEcho: Got sig 0x22c61241, not 0x594e4f54 !

 .... 

Apr 5 12:17:01 vpn-01 ppp[3951]: tun1: Phase: deflink: ** Too many LCP ECHO packets lost **

Первая строка говорит о том что lqr.magic в полученном пакете не верен.

Вторая строка появится после того как вы 5-ть раз увидете по данному туннелю первую строчку и затем данный туннель будет отключен принудительно.

Затем юзер реконнектнется и все повторится с начала…. и так до бесконечности.

Причина такого поведения в том, что некоторые производители домашних роутеров срут на стандарты при реализации протокола и отсюда все проблемы.

Что же с этим делать ?

Вариантов несколько:

1. отключить LQR совсем
2. позвонить пользователю и сказать что его роутер не годен для работы в вашей сети
3. ковырять и править исходники ppp

Отключать LQR совсем не вариант, т.к. тогда зависший туннель точно никогда не отвалится, а это не есть гуд. Предлагать пользователю сменить роутер равнозначно предложить ему сменить провайдера.

Получается что остается один вариант —  ковырять исходники ppp и нужно сделать так, чтобы  не было реагирования на состав меджика.

Для FreeBSD 8.2 это будет происходить так:

Идем в сорцы /usr/src/usr.sbin/ppp/ и находим в этой папке файл lqr.c.
Правим его, diff можно увидеть тут. А именно просто комментарим тот IF, который проверяет меджик, выводит нам сообщение и не увеличивает каунтер полученных LCP пакетов.

Затем делаем make и после чего в /usr/obj/usr/src/usr.sbin/ppp появится вновь собранный файл ppp.
Теперь наша задача плавно перевести пользователей на вновь собранный демон, т.к. тупо заменить им текущий может и не получится в виду того, что на каждый PPPoE туннель создается отдельный процесс:

97011 ?? Ss 0:03,33 /usr/sbin/ppp -direct pppoe

и фря может отказать вам в замене файла.

То у нас три варианта:

• перезапустить сервер
• убить все процессы ppp
• вызывать новый ppp только при новых подключениях

Действуем по последнему варианту, т.к. это позволит плавно перевести пользователй, ведь рано или поздно все переподключатся и мы сможем заменить старый /usr/sbin/ppp.

Берем новый ppp и копируем в /usr/sbin/ppp.new.

Не забудьте выставить владельца и права на новый файл так же как это было у старого:

-r-sr-x---  1 root  network  412608 26 Apr 13:14 /usr/sbin/ppp

# chmod 4550 /usr/sbin/ppp.new
# chgrp network /usr/sbin/ppp.new

Затем убиваем все процессы pppoed и стартуем их снова, но чуть изменив строку запуска:

# /usr/libexec/pppoed -a vpn-01 -p "*" -e "/usr/sbin/ppp.new -direct pppoe" em1

Что при подключении пользователя запустит уже не /usr/sbin/ppp, а /usr/sbin/ppp.new.

После того как все готово можно посмотреть как подключаются пользователи и убедиться в том, что Warning: lqr_RecvEcho более не появляется, а пользователи, которые из-за этого отваливались, более не отваливаются.

Как только процессов ppp не останется, мы сможем заменить старый новым и вернуть строку запуска pppoed к прежней.

Ещё одно полезное дополнение для pppoed это дополнить информацию в его логах.

По дефотлу подключение клиента в /var/log/pppoed.log выглядит так:

Apr 5 09:34:19 vpn-01 pppoed[58768]: Listening as provider * 

Apr 5 09:34:19 vpn-01 pppoed[58904]: Offering to .:exec-58904 as access concentrator vpn-01 

Apr 5 09:34:19 vpn-01 pppoed[58904]: adding to .:exec-58904 as offered service vpn-01 

Apr 5 09:34:19 vpn-01 pppoed[58904]: Received NGM_PPPOE_SESSIONID (hook "^C") 

Apr 5 09:34:19 vpn-01 pppoed[58904]: Received NGM_PPPOE_SUCCESS (hook "exec-58904") 

Apr 5 09:34:19 vpn-01 pppoed[58904]: Executing: exec /usr/sbin/ppp -direct pppoe

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

Apr 5 09:00:52 vpn-01 pppoed[73025]: Offering to .:exec-73025 as access concentrator vpn-01 at [vlan65] 

Apr 5 09:00:52 vpn-01 pppoed[73025]: adding to .:exec-73025 as offered service vpn-01 at [vlan65] 

Apr 5 09:00:52 vpn-01 pppoed[73025]: Received NGM_PPPOE_SESSIONID (hook "ü ÿÿÿ^?") [40:4a:03:a8:e3:a0] at [vlan65] 

Apr 5 09:00:52 vpn-01 pppoed[73025]: Received NGM_PPPOE_SUCCESS (hook "exec-73025") [40:4a:03:a8:e3:a0] at [vlan65] 

Apr 5 09:00:52 vpn-01 pppoed[73025]: Executing: exec /usr/sbin/ppp -direct pppoe for .:exec-73025: [40:4a:03:a8:e3:a0] at [vlan65]

Так становится более понятнее о том к какому клиенту относятся строчки в логе и за каким интерфейсом сервера расположен клиент.

З.Ы. При копировании статьи ссылка на источник ОБЯЗАТЕЛЬНА ! Пожалуйста, уважайте чужой труд.

Авторы: Николаев Дмитрий (virus (at) subnets.ru) и Панфилов Алексей (lehis (at) subnets.ru)