сообщения [debug] от audiohook.c
| Код: |
| [Jul 30 07:42:13] DEBUG[4735] audiohook.c: Read factory 0x8453050 was pretty quick last time, waiting for them. .. [Jul 30 07:42:22] DEBUG[4735] audiohook.c: Write factory 0x8453a6c was pretty quick last time, waiting for them. .. |
Сообщения такого рода появляются в любом логе, содержащем вывод debug. Причем, частота их появления около 50 строк в секунду, поэтому логи растут с бешеной скоростью и что либо в них потом искать - "нереально". Logrotate в шоке от объемов, которые ему приходиться вертеть
Немного о самой проблеме:
Такие сообщения были замечены всего на двух серверах без телефонных плат расширения. Появляются только в том случае, если разговор записывается, т.е. используется application MixMonitor перед Dial. Каналы связи только SIP. Affected версии asterisk >= 1.4.18. Насколько я понял, сообщение связано с изменениями: 2008-01-16 20:34 +0000 [r98966-98973]. (я предполагаю, issue id: 0011945).
Я копал в сторону таймера (ztdummy), т.к. сообщение валится после
| Код: |
| channel.c: Scheduling timer at 160 sample intervals |
Пробовал RTC/ High Resolution Timer/Таймер из uhci_hcd - ничего не помогает, ситуация не меняется.
Загрузка cамого ztdummy:
RTC:
| Код: |
| ztdummy: RTC rate is 1024 |
HiResTimer:
| Код: |
| ztdummy: Trying to load High Resolution Timer ztdummy: Initialized High Resolution Timer ztdummy: Starting High Resolution Timer ztdummy: High Resolution Timer started, good to go |
Чтение исходников глаза не открыло. В bugs.digium кто-то об уже упомянул о таких сообщениях, но получил ответ типа "ничего удивительного, что в лог с debugом вы получаете сообщения о debugе"
Закомментировать вывод этого сообщения в исходнике - не вариант. Хочется докопаться до причины. На одном сервере откатился до 1.4.17, на другом до сих порт получаю эти сообщения.
Загруженность серверов load average: 0.05, 0.06, 0.01,
Скорость обмена данными с жесткими дисками (не знаю, нужно ли):
Timing cached reads: 1060 MB in 2.00 seconds = 529.70 MB/sec
Timing buffered disk reads: 194 MB in 3.01 seconds = 64.46 MB/sec
Один сервер
| Код: |
| 2.6.24-gentoo-r8 #1 SMP Mon Jun 30 18:52:45 MSD 2008 i686 Intel(R) Xeon(R) CPU 5120 @ 1.86GHz GenuineIntel GNU/Linux |
Другой
| Код: |
| Debian 2.6.18-4-686 #1 SMP Mon Mar 26 17:17:36 UTC 2007 i686 GNU/Linux |
При этом записанные разговоры целые, без хлюпанья, синхронизированные. Сами разговоры не рвутся. Системные логи чистые, без ошибок. Полный лог звонка во вложении.
| Код: |
| [options] ... internal_timing = yes ... |
Менял в "no", ситуации не меняется.
В данной ситуации можно в исходном коде увеличить установленный уровень для вывода данного сообщения (цифра в core set debug).
_________________
OpenSUSE 11.2 / Asterisk-trunk / Celeron 1100 (512mb) / chan_lcr / Linksys / Aastra 9112i
http://igorg.ru
[DEBUG] audiohook.c Failed to get 160 samples from read factory
?
Added after 25 minutes:
во, я проследил цепочку
Как я уже сказал, "ошибка" вылетает после app_mixmonitor.
из app_mixmonitor.c, когда пошла запись, крутиться этот цикл:
| Код: |
| ... while (mixmonitor->audiohook.status == AST_AUDIOHOOK_STATUS_RUNNING) { struct ast_frame *fr = NULL; ast_audiohook_trigger_wait(&mixmonitor->audiohook); if (mixmonitor->audiohook.status != AST_AUDIOHOOK_STATUS_RUNNING) break; if (!(fr = ast_audiohook_read_frame(&mixmonitor->audiohook, SAMPLES_PER_FRAME, AST_AUDIOHOOK_DIRECTION_BOTH, AST_FORMAT_SLINEAR))) continue; ... |
Который запустил функцию ast_audiohook_read_frame, далее работает audiohook.c
| Код: |
| ... struct ast_frame *ast_audiohook_read_frame(struct ast_audiohook *audiohook, size_t samples, enum ast_audiohook_direction direction, int format) { struct ast_frame *read_frame = NULL, *final_frame = NULL; if (!(read_frame = (direction == AST_AUDIOHOOK_DIRECTION_BOTH ? audiohook_read_frame_both(audiohook, samples) : audiohook_read_frame_single(audiohook, samples, direction)))) return NULL; |
Внутри этой функции работает функция чтения samples, в моем случае это audiohook_read_frame_both. Только вот что она делает, я не понимаю
Added after 12 minutes:
Дело в том, что это сообщение стало сопровождаться глюками системы!
* пишу sip debug, а консоль просто переходит на новую строку
* пишу sip show registry - нет вывода
* звонки не ходят, пакеты не показываются (т.к. sip debug не работает)
* restart now свою работу не делает О_о
dmesg чист.
После "kill -9 pid_астерсика" и запуска астериска заново положительного результата нет (демон запущен, но обрабатывается только zap).
Помог reboot сервака.
Товарищи, не может ли это быть проблема с памятью? Т.к. сэмплы читаются из буфера и им там чего-то не хватает, может быть у меня с оперативкой что-то? Но, опять же, не на 3х серваках-то. Может криво собрано ядро? Ядра собираем из портов, просто конфигурим под своё железо (проц/дрова под девайсы).
Сервак ребутаем раз в месяц в профилактических целях.
| Код: |
| # dmesg | grep -i mem Memory: 446160k/457664k available (1499k kernel code, 10848k reserved, 599k data, 256k init, 0k highmem) Freeing initrd memory: 4246k freed MEM window: fd800000-fd8fffff MEM window: fde00000-fdefffff MEM window: fdc00000-fdcfffff MEM window: fdb00000-fdbfffff Freeing unused kernel memory: 256k freed ohci_hcd 0000:00:0b.0: irq 209, io mem 0xfe02f000 ehci_hcd 0000:00:0b.1: irq 217, io mem 0xfe02e000 |
Added after 11 minutes:
Ребят, а какой есть visual дебагер?
Added after 39 minutes:
На кривом английском отписал в http://bugs.digium.com/view.php?id=13116
Пришел ответ с bug.digium:
| Цитата: |
| c0rnoTa: Those messages are happening due to the way in which the audiohook on a MixMonitor works. If you look at issue 0013005 and apply the last patch there (called 13005_final.patch) those messages should go away. I'll take a closer look at the possible ramifications of fax and mixmonitor. |
Согласно http://bugs.digium.com/view.php?id=13005, проблема рассинхронизации возникает до сих пор (даже на 1.4.21.2), но патч called 13005_final.patch должен решить проблему.
С понедельника приступлю к тестированию на двух серваках.
Подчеркну, что unaffected версии астериска это 1.4.17 и 1.4.19.1. Но в них своих багов хватает! (самый яркий - в 1.4.17 bug в распознавании dtmf, так что перед тем как откатываться, подумайте трижды. После того как решитесь, еще раз трижды подумайте.)
Смотрите патч от putnopvut на http://bugs.digium.com/view.php?id=13005
там же есть и объяснение проблемы.
Обновил на тестовой машине Астер до версии 1.6.0.1. В лог пишутся такие же сообщения. Я правильно понимаю, что патч, устраняющий данную проблему на данный момент выпущен только для версии 1.4? Или же этот патчик подойдет и для моего "Астера"?
Если посмотреть текст патча - можно понять, что и как надо поправить. Поправил - работает и на 1.6 ) Лог теперь вполне адекватный.
Столкнулся с такой же проблемой на asterisk 1.6.2.
2012-09-23 15:07:49] DEBUG[13601]: audiohook.c:221 audiohook_read_frame_both: Write factory 0x1d68748 was pretty quick last time, waiting for them.
В результате, некоторые разговоры не пишутся (файл не создается). Бывает лагает связь, фонит, эхо, пропадают слова при разговоре. Можете подробнее описать решение?
на 11-м астериске проблема по-прежнему актуальна