Jump to content
Как правильно добавить self-test и прочую отладку в тему
Где взять тестовые сборки
  • 0
Followers 1
OmegaTron

Statistics collector thread holds ULTIMATE (255) lock xxx seconds acquired

Asked by OmegaTron

Question

02/11/2018 06:06 AM

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

2018-02-11 15:11:08    User.Warning    192.168.0.1    Feb 11 15:10:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 24780 seconds acquired Feb 11 08:17:05.
2018-02-11 15:11:08    User.Warning    192.168.0.1    Feb 11 15:10:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 24775 seconds acquired Feb 11 08:17:10.
2018-02-11 15:11:08    User.Warning    192.168.0.1    Feb 11 15:10:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 24774 seconds acquired Feb 11 08:17:11.
2018-02-11 15:11:08    User.Warning    192.168.0.1    Feb 11 15:10:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8226 seconds acquired Feb 11 12:52:59.
2018-02-11 15:12:07    User.Warning    192.168.0.1    Feb 11 15:11:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 24840 seconds acquired Feb 11 08:17:05.
2018-02-11 15:12:07    User.Warning    192.168.0.1    Feb 11 15:11:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 24835 seconds acquired Feb 11 08:17:10.
2018-02-11 15:12:07    User.Warning    192.168.0.1    Feb 11 15:11:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 24834 seconds acquired Feb 11 08:17:11.
2018-02-11 15:12:08    User.Warning    192.168.0.1    Feb 11 15:11:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8286 seconds acquired Feb 11 12:52:59.
2018-02-11 15:13:07    User.Warning    192.168.0.1    Feb 11 15:12:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 24900 seconds acquired Feb 11 08:17:05.
2018-02-11 15:13:07    User.Warning    192.168.0.1    Feb 11 15:12:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 24895 seconds acquired Feb 11 08:17:10.
2018-02-11 15:13:07    User.Warning    192.168.0.1    Feb 11 15:12:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 24894 seconds acquired Feb 11 08:17:11.
2018-02-11 15:13:08    User.Warning    192.168.0.1    Feb 11 15:12:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8346 seconds acquired Feb 11 12:52:59.
2018-02-11 15:14:07    User.Warning    192.168.0.1    Feb 11 15:13:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 24960 seconds acquired Feb 11 08:17:05.
2018-02-11 15:14:07    User.Warning    192.168.0.1    Feb 11 15:13:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 24955 seconds acquired Feb 11 08:17:10.
2018-02-11 15:14:07    User.Warning    192.168.0.1    Feb 11 15:13:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 24954 seconds acquired Feb 11 08:17:11.
2018-02-11 15:14:08    User.Warning    192.168.0.1    Feb 11 15:13:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8406 seconds acquired Feb 11 12:52:59.
2018-02-11 15:15:06    User.Warning    192.168.0.1    Feb 11 15:14:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 25020 seconds acquired Feb 11 08:17:05.
2018-02-11 15:15:07    User.Warning    192.168.0.1    Feb 11 15:14:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 25015 seconds acquired Feb 11 08:17:10.
2018-02-11 15:15:07    User.Warning    192.168.0.1    Feb 11 15:14:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 25014 seconds acquired Feb 11 08:17:11.
2018-02-11 15:15:08    User.Warning    192.168.0.1    Feb 11 15:14:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8466 seconds acquired Feb 11 12:52:59.
2018-02-11 15:16:06    User.Warning    192.168.0.1    Feb 11 15:15:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 25080 seconds acquired Feb 11 08:17:05.
2018-02-11 15:16:06    User.Warning    192.168.0.1    Feb 11 15:15:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 25075 seconds acquired Feb 11 08:17:10.
2018-02-11 15:16:07    User.Warning    192.168.0.1    Feb 11 15:15:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 25074 seconds acquired Feb 11 08:17:11.
2018-02-11 15:16:07    User.Warning    192.168.0.1    Feb 11 15:15:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8526 seconds acquired Feb 11 12:52:59.
2018-02-11 15:17:07    User.Warning    192.168.0.1    Feb 11 15:16:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 25140 seconds acquired Feb 11 08:17:05.
2018-02-11 15:17:07    User.Warning    192.168.0.1    Feb 11 15:16:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 25135 seconds acquired Feb 11 08:17:10.
2018-02-11 15:17:07    User.Warning    192.168.0.1    Feb 11 15:16:06 ndm: Core::Watchdog: Interface Bridge0 neighbour explorer holds ARP_TABLE (57) lock 25134 seconds acquired Feb 11 08:17:11.
2018-02-11 15:17:08    User.Warning    192.168.0.1    Feb 11 15:16:06 ndm: Core::Watchdog: Event sender holds CORE (2) lock 8586 seconds acquired Feb 11 12:52:59.
2018-02-11 15:18:06    User.Warning    192.168.0.1    Feb 11 15:17:05 ndm: Core::Watchdog: Statistics collector thread holds ULTIMATE (255) lock 25200 seconds acquired Feb 11 08:17:05.
2018-02-11 15:18:06    User.Warning    192.168.0.1    Feb 11 15:17:05 ndm: Core::Watchdog: Timer holds CORE (2) lock 25195 seconds acquired Feb 11 08:17:10.

 

Увидев строки "core" и "Watchdog" подумал, что роутер основательно залип - так и оказалось. Telnet не отвечал, ssh из комплекта entware не отвечал (соединение вроде устанавливалось, но залипало и висело), коннекта к интернету не было. Единственное, что хоть что-то отвечало - это веб-фейс. После авторизации он отображался, но на динамически обновляемых блоках висел прогресс-бар, который крутился бесконечно. Спустя пару минут в веб-фейсе появлялись ошибки "error: not responded" (или типа того) и восклицательный знак в углу, а в syslog валилось 

2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1406) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245
2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1400) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245

Попытался ребутнуть роутер через CI, получил ответ 

<packet>
    <response id="0">
        <message>rebooting the system</message>
    </response>
</packet>

но ребута не случилось (выждал минут 5) и роутер пришлось дёргать по питанию. После включения сообразил, что можно было дёрнуть через CI лог, но было уже поздно :( Сегодня займусь установкой syslog-ng (или как его там), надоели уже такие случаи.

 

Теперь вопрос - что это могло быть ?

Share this post

Link to post
Share on other sites

20 answers to this question

Recommended Posts

  • 0
02/11/2018 08:26 AM

Нужен весь вывод syslog, в том числе и то, что случилось 25 тысяч секунд до этого куска.

А версия  прошивки-то хоть какая?

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:19 AM (edited)
55 минут назад, Le ecureuil сказал:

Нужен весь вывод syslog, в том числе и то, что случилось 25 тысяч секунд до этого куска.

Комп до этого был выключен - эти цикличные блоки данных всё, что насыпалось в syslog. Адреса log.txt я на тот момент не знал (сейчас уже поглядел), а через CI/RCI дёрнуть лог не сообразил. Хотя я сомневаюсь, что он вообще бы отдался при такой клинике - там get/post запросы проходили с минутными задержками.

55 минут назад, Le ecureuil сказал:

А версия  прошивки-то хоть какая?

Дык в подписи - 2.10.C.2.0-4

Ещё момент - в entware кроме базового dropbear'a никакого софта нет, равно как и скриптов в автозагрузке. Руки до этого не дошли.

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

Edited by OmegaTron

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:24 AM
4 минуты назад, OmegaTron сказал:

Дык в подписи - 2.10.C.2.0-4

Если с мобильных устройств заходить, то подпись не видна.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:27 AM
1 минуту назад, AndreBA сказал:

Если с мобильных устройств заходить, то подпись не видна.

Угу, вижу. Как раз пишу со смарта.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:27 AM
3 hours ago, OmegaTron said:

Теперь вопрос - что это могло быть ?

Нужен был self-test или вывод "show threads" + log.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:33 AM
3 минуты назад, sergeyk сказал:

Нужен был self-test или вывод "show threads" + log.

На момент висяка или на текущий момент ? Если первое, то врятли это было бы возможно ибо веб-морда зависала, а прямых линков файлов я на тот момент не знал. ОК, буду иметь ввиду, что смотреть.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 09:35 AM
2 minutes ago, OmegaTron said:

На момент висяка или на текущий момент ? Если первое, то врятли это было бы возможно ибо веб-морда зависала, а прямых линков файлов я на тот момент не знал. ОК, буду иметь ввиду, что смотреть.

В момент вывода сообщений.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:11 PM (edited)
3 часа назад, sergeyk сказал:

В момент вывода сообщений.

ОК. Главное, чтобы хоть что-то при этом отвечало - telnet/ssh/web. В данном случае работал web, да и то только через запросы к CI/RCI через curl/wget.

Раз пошла такая пьянка - как через ssh имея доступ к корню дёрнуть упомянутые данные ? А то не так давно был сбой при котором был доступ лишь через ssh, а всё остальное отвалилось.

Edited by OmegaTron

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:13 PM
1 минуту назад, OmegaTron сказал:

ОК. Главное, чтобы хоть что-то при этом отвечало - telnet/ssh/web. В данном случае работал web, но только через запросы к CI/RCI через curl/wget.

Раз пошла такая пьянка - как через ssh имея доступ к корню дёрнуть упомянутые данные ? А то не так давно был сбой при котором был доступ лишь через ssh, а всё остальное отвалилось.

Почти никак. Нужен syslog с внешним сохранением.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:17 PM
2 минуты назад, Le ecureuil сказал:

Почти никак. Нужен syslog с внешним сохранением.

Мне казалось лог хранится где-то типа /var/run/log Вроде ж должна быть локальная копия куда пишется журнао отображаемый в веб-фейсе.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:18 PM
Только что, OmegaTron сказал:

Мне казалось лог хранится где-то типа /var/run/log Вроде ж должна быть локальная копия куда пишется журнао отображаемый в веб-фейсе.

Он существует только в ОЗУ в процессе ndm.

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:19 PM
6 minutes ago, OmegaTron said:

ОК. Главное, чтобы хоть что-то при этом отвечало - telnet/ssh/web. В данном случае работал web, но только через запросы к CI/RCI через curl/wget.

Раз пошла такая пьянка - как через ssh имея доступ к корню дёрнуть упомянутые данные ? А то не так давно был сбой при котором был доступ лишь через ssh, а всё остальное отвалилось.

Проще всего, пожалуй, через браузер 

http://192.168.1.1/rci/show/threads
http://192.168.1.1/rci/more?filename=log

 

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:26 PM
1 минуту назад, sergeyk сказал:

Проще всего, пожалуй, через браузер

В том случае

1 минуту назад, sergeyk сказал:

доступ лишь через ssh, а всё остальное отвалилось.

В данном случае, веб-морда не отвечала и через минуту отваливалась 

2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1406) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245
2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1400) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245

Так что не проще. Если по этим запросам

3 минуты назад, sergeyk сказал:

http://192.168.1.1/rci/show/threads

http://192.168.1.1/rci/more?filename=log

отдаются txt, как в случае с */ci/* то можно попробовать в следующий раз слить через curl/wget,  хотя я лучше поступлю более радикально https://forum.keenetic.net/topic/527-запись-syslog-на-внешний-usb-диск-с-помощю-syslog-ng/

Share this post

Link to post
Share on other sites
  • 0
02/11/2018 01:30 PM
2 minutes ago, OmegaTron said:

В том случае

В данном случае, веб-морда не отвечала и через минуту отваливалась 


2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1406) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245
2018-02-11 15:33:51    Daemon.Error    192.168.0.1    Feb 11 15:32:50 keenetic_omni nginx: (conn: *1400) upstream timed out (145: Unknown error) while reading response header from upstream, client: 192.168.0.245

Так что не проще. Если по этим запросам

отдаются txt, как в случае с */ci/* то можно попробовать в следующий раз слить через curl/wget,  хотя я лучше поступлю более радикально https://forum.keenetic.net/topic/527-запись-syslog-на-внешний-usb-диск-с-помощю-syslog-ng/

Через ssh запускайте ndmc 

(config)> show threads
(config)> more log

Просто журнал — это хорошо, но очень желательно видеть еще и состояние потоков.

Share this post

Link to post
Share on other sites
  • 0
02/15/2018 04:01 PM
1 час назад, ndm сказал:

@OmegaTron: ситуация должна заметно улучшиться в версии 2.12.A.3.0-4.

Вы расскажите, в чём цимес ситуации и почему роутер тогда повисал.

Касательно установки 2.12 - я хз, мне в соседней ветке писали что прошивки из этого "эшелона" чересчур тяжёлые.

Share this post

Link to post
Share on other sites
  • 0
02/15/2018 05:17 PM
1 час назад, OmegaTron сказал:

Вы расскажите, в чём цимес ситуации и почему роутер тогда повисал.

Касательно установки 2.12 - я хз, мне в соседней ветке писали что прошивки из этого "эшелона" чересчур тяжёлые.

Вам слово netlink о чем-нибудь говорит?

Share this post

Link to post
Share on other sites
  • 0
02/20/2018 10:08 PM
В 16.02.2018 в 03:17, Le ecureuil сказал:

Вам слово netlink о чем-нибудь говорит?

Нет. Т.е. объяснения для дилентантов не будет ? Хотя бы в общих чертах ?)

Share this post

Link to post
Share on other sites
  • 0
02/21/2018 07:21 AM
9 часов назад, OmegaTron сказал:

Нет. Т.е. объяснения для дилентантов не будет ? Хотя бы в общих чертах ?)

В общих чертах - при считывании ARP-таблицы из ядра по netlink происходило блокирование операции I/O на этом сокете, в итоге этот поток зависал с захваченным mutex, и вызывал зависание других потоков, также пытающихся захватить этот mutex.

Share this post

Link to post
Share on other sites

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Answer this question...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.

×
Followers 1
Go to question listing

  • Recently Browsing   0 members

    No registered users viewing this page.

×
×
  • Create New...