Страницы

rancid: missed cmd(s): show running-config

Наткнулся на интересную проблему с rancid:

Уведомление от rancid

Date: Sat, 15 Oct 2016 06:02:09 +0600
Subject: config fetcher problems - GroupName
The following routers have not been successfully contacted for
more than 24 hours.
-rw-r-----. 1 rancid netadm 46484 Oct 14 06:01 DeviceName

Логи от rancid

starting: Sat Oct 15 06:00:01 ALMT 2016

property 'svn:ignore' set on '.'
property 'svn:ignore' set on 'configs'
Updating '.':
At revision 48.


Trying to get all of the configs.
alacr02.basu: missed cmd(s): show running-config
=====================================
Getting missed routers: round 1.
alacr02.basu: missed cmd(s): show running-config
=====================================
Getting missed routers: round 2.
alacr02.basu: missed cmd(s): show running-config
=====================================
Getting missed routers: round 3.
alacr02.basu: missed cmd(s): show running-config
=====================================
Getting missed routers: round 4.
alacr02.basu: missed cmd(s): show running-config


ending: Sat Oct 15 06:02:09 ALMT 2016

При этом по логам tac_plus команда show running-config и другие были выполнены корректно:
2016-10-15 06:00:21 +0600       DeviceIP     rancid  tty2    tac_plusIP stop    task_id=52693   
timezone=Almaty service=shell   start_time=1476489621   priv-lvl=15     cmd=show running-config 

Анализ предыдущих логов от rancid показал, что эта проблема периодически всплывала, просто в этот раз ошибка произошла целых 5 раз подряд, поэтому rancid и забил тревогу (ранее проблема возникала не более 5 раз подряд, т.е. со второго-третьего раза комнада выполнялась успешно и этого было достаточно).

В качестве возможного варианта я предположил, что конфигурация стала выдаваться дольше чем ранее и rancid, не дождавшись ответа, останавливает процесс. Здесь нашёл как запустить rancid в режиме дебага, но в данном случае вывод мало чем помог – команды вроде как выполняются, но в конце выясняется, что проблема всё-таки есть.

[rancid@nms ~]$ rancid -d -t cisco DeviceName
loadtype: device type cisco
loadtype: found device type cisco in /home/rancid/etc/rancid.types.base
executing clogin -t 90 -c"show version;show redundancy secondary;...;...;show running-config;write term" DeviceName
PROMPT MATCH: SW#
HIT COMMAND:SW#show version
    In ShowVersion: SW#show version
TYPE = 3500XL
HIT COMMAND:SW#show redundancy secondary
    In ShowRedundancy: SW#show redundancy secondary
...
...
HIT COMMAND:SW#more system:running-config
    In WriteTerm: SW#more system:running-config
HIT COMMAND:SW#write term
    In WriteTerm: SW#write term
DeviceName: missed cmd(s): show running-config
DeviceName: missed cmd(s): show running-config
[rancid@nms ~]$
[rancid@nms ~]$ ls -la DeviceName*
-rw-r--r--. 1 rancid netadm  46629 Oct 15 13:34 DeviceName.new
-rw-r--r--. 1 rancid netadm 309045 Oct 15 13:34 DeviceName.raw

Файл .new содержит результат, полученный после обработки rancid'ом вывода команд. Файл .raw содержит больше информации – тут показан не только результат работы rancid, но сам процесс ввода команд, а также их вывода. Анализ последнего показал, что команда show running-config вводится некорректно:

!^M
end^M
^M
SW#ning-config^M
Building configuration...^M
^M
Эта часть файла навела на мысль о том, что в какой-то момент rancid "теряет" сессию и "думает", что пора вводить команду, хотя этого, на самом деле, делать не следует.

Для того, чтобы получить больше вывода было предложено выставить переменную NOPIPE в значение YES (вариант 5 по ссылке выше), но, не разобравшись с этой переменной, я реализовал другое решение – временно закоментировал в /home/rancid/bin/rancid те участки кода, которые проверяют эту переменную:
#    if (defined($ENV{NOPIPE}) && $ENV{NOPIPE} =~ /^YES/i) {
        system "$lscript -t $timeo -c \"$commandstr\" $host </dev/null > $host.raw 2>&1" || die "clogin failed for $host: $!\n";
        open(INPUT, "< $host.raw") || die "clogin failed for $host: $!\n";
#    } else {
#       open(INPUT,"$lscript -t $timeo -c \"$commandstr\" $host </dev/null |") || die "clogin failed for $host: $!\n";
#    }
...
...
#if (defined($ENV{NOPIPE}) && $ENV{NOPIPE} =~ /^YES/i) {
    unlink("$host.raw") if (! $debug);
#}

и снова запустил rancid в режиме дебага, правда в этот раз он выдал гораздо больше информации:
[rancid@nms ~]$ ls -la DeviceName*
-rw-r--r--. 1 rancid netadm  3033556 Oct 15 17:49 DeviceName.new
-rw-r--r--. 1 rancid netadm 20074348 Oct 15 17:49 DeviceName.raw
Обратите внимание, что теперь .raw файл уже содержит не 309045, а 20074348 байт :).

Решение проблемы

Путём скурпулёзного вчитывания в сырой и вырвиглазный вывод работы rancid было выяснено, что я очень неудачно выбрал название своего устройства (SW). Это стало понятно по следующим строчкам:
expect: does "SW  PID                 Serial#     Status           Sys Pwr  PoE Pwr  Watts\r\n---  ------------------  ----------  ---------------  -------  -------  -----\r\n1A  C3KX-PWR-350WAC     DCB173092W2 OK              Good     Good     350/0\r\n1B  Not Present       \r\n\r\nSW  Status          RPS Name          RPS Serial#  RPS Port#\r\n--  -------------   ----------------  -----------  ---------\r\n1   Not Present     <>\r\n\r\n\r\nSW#" (spawn_id exp4) match regular expression "\u0008+"? (No Gate, RE only) gate=yes re=no^M
"^[^\n\r *]*SW([^#>\r\n]+)?[#>](\\([^)\\r\\n]+\\))?"? Gate "*SW*"? gate=yes re=yes^M

Кстати, это строчки с номерами 2172 и 2173, а в дебаге таких строк – 94467 штук :). Беда в том, что rancid решил, что строчка
SW  PID                 Serial#     Status           Sys Pwr  PoE Pwr  Watts\r\n
в выводе команды show env all соответствует окончанию вывода всей команды, т.к. часть этой строки подходит под выражение ^[^\n\r *]*SW([^#>\r\n]+)?[#>](\\([^)\\r\\n]+\\))? (это видно по окончанию gate=yes re=yes). Расшифровывать что означает вышеуказанная дикая последовательность символов я не буду, так как на это у меня уйдёт слишком много времени :). Скажу лишь, что стало понятно, что rancid принимает одну из строк вывода команды show env all за hostname устройства с приглашением командной строки (SW#) и, вместо анализа необработанного буфера, начинает вводить следующие команды.

В итоге получается, что rancid остаётся "позади текущих событий" (писать под диктовку, отставая от диктующего на несколько предложение, далеко не самое приятное занятие). И хотя, большую часть времени, rancid успевает корректно обрабатывать вывод команд (хоть и с опозданием), иногда это не срабатывает (скорее всего по причине немалых задержек при ожидании вывода show running-config) и rancid "ловит" ошибку.

По-хорошему желательно сообщить об этом команде rancid, возможно они смогут принять меры. К тому же (вероятно?) это сможет помочь и в каких-либо других ситуациях, но на данный момент решением проблемы выступило банальное переименование устройства в соответствии с уже определённой схемой.

P.S. А переименуй я устройство неделей ранее и я бы так и не узнал о таком баге :).

Полезные ссылки:

Useful RANCID Debugging Tips

1 комментарий:

  1. Mr. Trump | Casino and Hotel: NJ Archives - DRMCD
    In addition to 보령 출장안마 a 경산 출장안마 24-hour casino, the casino also features a 24-hour 보령 출장샵 bar and a sports bar. The casino also 서산 출장안마 includes 의정부 출장샵 a sports bar, a spa and a nightclub.

    ОтветитьУдалить