Не понятное поведение агента

[mkolomiets]

Добрый день!
Изредка проявляется такой эффект - в процессе работы агент перестает опрашивать датчики и связываться с сервером, обычно это происходит после пропадания связи (агенты работают на узлах, где может быть достаточно неустойчивая связь).
Причем часто после появления связи агент все равно не восстанавливает нормальную работу. У нас мониторится порядка 130 узлов, поэтому данный эффект проявляется достаточно регулярно.

ЗЫ. Я дорабатывал код агента для возможности работы с сервером через несколько адресов, но с недоработанными агентами происходит то же самое.

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

[COLOR="red"]Со связью все еще в порядке[/COLOR]
  1214:20110127:004523.451 For key [net.tcp.service.perf[http, www.google.com, 80]] received value [0.279653]
  1214:20110127:004523.451 In process_value() key:'xxxx-xxxxxxxxxxx:net.tcp.service.perf[http, www.google.com, 80]' value:'0.279653'
  1214:20110127:004523.452 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:8/100
  1214:20110127:004523.453 Will not send now. Now 1296081923 lastsent 1296081896 < 30
  1214:20110127:004523.453 End of send_buffer():SUCCEED
  1214:20110127:004523.454 Buffer: new element 8
  1214:20110127:004523.454 In get_min_nextcheck()
  1214:20110127:004523.455 Sleeping for 1 seconds
  1214:20110127:004524.456 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:9/100
  1214:20110127:004524.456 Will not send now. Now 1296081924 lastsent 1296081896 < 30
  1214:20110127:004524.457 End of send_buffer():SUCCEED
  1214:20110127:004524.458 Sleeping for 1 seconds
  1213:20110127:004524.804 In collector_diskdevice_get("")
  1214:20110127:004525.458 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:9/100
  1214:20110127:004525.459 Will not send now. Now 1296081925 lastsent 1296081896 < 30
  1214:20110127:004525.460 End of send_buffer():SUCCEED
  1214:20110127:004525.460 Sleeping for 1 seconds
[COLOR="red"]Где то здесь связь упала[/COLOR]
  1214:20110127:004526.461 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:9/100
  1214:20110127:004527.590 JSON before sending [{
	"request":"agent data",
	"data":[
		{
			"host":"xxxx-xxxxxxxxxxx",
			"key":"net.tcp.service.perf[http, 172.20.1.251, 80]",
			"value":"0.000000",
			"clock":1296081902},
[COLOR="red"]Выкушен кусок[/COLOR]
		{
			"host":"xxxx-xxxxxxxxxxx",
			"key":"net.tcp.service.perf[http, www.google.com, 80]",
			"value":"0.279653",
			"clock":1296081923}],
	"clock":1296081926}]
  1213:20110127:004625.074 In collector_diskdevice_get("")
  1213:20110127:004725.348 In collector_diskdevice_get("")
  1213:20110127:004825.790 In collector_diskdevice_get("")
  1213:20110127:004926.053 In collector_diskdevice_get("")
  1213:20110127:005026.321 In collector_diskdevice_get("")
  1213:20110127:005126.609 In collector_diskdevice_get("")
  1213:20110127:005226.867 In collector_diskdevice_get("")
  1213:20110127:005327.124 In collector_diskdevice_get("")
  1213:20110127:005427.391 In collector_diskdevice_get("")
  1213:20110127:005527.666 In collector_diskdevice_get("")
  1213:20110127:005627.923 In collector_diskdevice_get("")
  1213:20110127:005728.381 In collector_diskdevice_get("")
  1213:20110127:005828.807 In collector_diskdevice_get("")
  1213:20110127:005929.187 In collector_diskdevice_get("")
  1213:20110127:010029.738 In collector_diskdevice_get("")
  1213:20110127:010130.098 In collector_diskdevice_get("")
  1214:20110127:010139.897 Send value error: [recv] ZBX_TCP_READ() failed [Network is unreachable]
  1214:20110127:010139.898 End of send_buffer():SUCCEED
  1214:20110127:010139.899 refresh_active_checks('x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171',10051)
  1214:20110127:010139.900 Trying next server address in list [x.x.x.227,x.x.x.226,x.x.x.171]
  1214:20110127:010139.901 Trying next server address in list [x.x.x.226,x.x.x.171]
  1214:20110127:010139.902 Trying next server address in list [x.x.x.171]
  1214:20110127:010139.903 Get active checks error: Cannot connect to [[x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171]:10051] [Network is unreachable]
  1214:20110127:010139.904 In process_active_checks('x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171',10051)
  1214:20110127:010139.904 For key [agent.ping] received value [1]
  1214:20110127:010139.905 In process_value() key:'xxxx-xxxxxxxxxxx:agent.ping' value:'1'
  1214:20110127:010139.906 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:0/100
  1214:20110127:010139.906 End of send_buffer():SUCCEED
  1214:20110127:010139.907 Buffer: new element 0
  1214:20110127:010139.908 For key [agent.version] received value [1.8.3]
  1214:20110127:010139.908 In process_value() key:'xxxx-xxxxxxxxxxx:agent.version' value:'1.8.3'
  1214:20110127:010139.909 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:1/100
  1214:20110127:010139.910 Trying next server address in list [x.x.x.227,x.x.x.226,x.x.x.171]
  1214:20110127:010139.911 Trying next server address in list [x.x.x.226,x.x.x.171]
  1214:20110127:010139.912 Trying next server address in list [x.x.x.171]
  1214:20110127:010139.914 Send value error: [connect] Cannot connect to [[x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171]:10051] [Network is unreachable]
  1214:20110127:010139.914 End of send_buffer():FAIL
  1214:20110127:010139.915 Buffer: new element 1
  1214:20110127:010139.917 TCP expect network error: Cannot connect to [[172.20.1.251]:80] [Network is unreachable]
[COLOR="red"]??? Минут 5-7 агент не снимал значения датчиков ???[/COLOR]
  1214:20110127:010139.917 For key [net.tcp.service.perf[http, 172.20.1.251, 80]] received value [0.000000]
  1214:20110127:010139.918 In process_value() key:'xxxx-xxxxxxxxxxx:net.tcp.service.perf[http, 172.20.1.251, 80]' value:'0.000000'
  1214:20110127:010139.919 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:2/100
  1214:20110127:010139.920 Trying next server address in list [x.x.x.227,x.x.x.226,x.x.x.171]
  1214:20110127:010139.921 Trying next server address in list [x.x.x.226,x.x.x.171]
  1214:20110127:010139.922 Trying next server address in list [x.x.x.171]
  1214:20110127:010139.923 Send value error: [connect] Cannot connect to [[x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171]:10051] [Network is unreachable]
  1214:20110127:010139.924 End of send_buffer():FAIL
  1214:20110127:010139.925 Buffer: new element 2
  1214:20110127:010142.926 Timeout while answering request
  1213:20110127:010231.012 In collector_diskdevice_get("")
  1213:20110127:010332.004 In collector_diskdevice_get("")
  1213:20110127:010432.611 In collector_diskdevice_get("")
  1213:20110127:010533.224 In collector_diskdevice_get("")
  1213:20110127:010633.904 In collector_diskdevice_get("")
  1213:20110127:010734.531 In collector_diskdevice_get("")
  1213:20110127:010835.111 In collector_diskdevice_get("")
  1213:20110127:010935.884 In collector_diskdevice_get("")
  1213:20110127:011036.682 In collector_diskdevice_get("")
  1213:20110127:011137.327 In collector_diskdevice_get("")
  1213:20110127:011237.867 In collector_diskdevice_get("")
  1213:20110127:011338.586 In collector_diskdevice_get("")
  1213:20110127:011440.014 In collector_diskdevice_get("")
  1213:20110127:011540.395 In collector_diskdevice_get("")
  1213:20110127:011640.667 In collector_diskdevice_get("")
[COLOR="red"]Связь вернулась[/COLOR]
  1214:20110127:011659.422 For key [net.tcp.service.perf[http, www.google.com, 80]] received value [919.496813]
[COLOR="red"]Судя по полученному значению все это время агент ждал именно этого датчика[/COLOR]
  1214:20110127:011659.423 In process_value() key:'xxxx-xxxxxxxxxxx:net.tcp.service.perf[http, www.google.com, 80]' value:'919.496813'
  1214:20110127:011659.424 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:3/100
  1214:20110127:011659.659 JSON before sending [{
	"request":"agent data",
	"data":[
		{
			"host":"xxxx-xxxxxxxxxxx",
			"key":"agent.ping",
			"value":"1",
			"clock":1296082899},
		{
			"host":"xxxx-xxxxxxxxxxx",
			"key":"agent.version",
			"value":"1.8.3",
			"clock":1296082899},
		{
			"host":"xxxx-xxxxxxxxxxx",
			"key":"net.tcp.service.perf[http, 172.20.1.251, 80]",
			"value":"0.000000",
			"clock":1296082899}],
	"clock":1296083819}]
  1214:20110127:011700.270 JSON back [{
	"response":"success",
	"info":"Processed 3 Failed 0 Total 3 Seconds spent 0.000048"}]
[COLOR="red"]Дальше вроди бы все стало на свои места[/COLOR]
  1214:20110127:011700.271 In check_response({
	"response":"success",
	"info":"Processed 3 Failed 0 Total 3 Seconds spent 0.000048"})
  1214:20110127:011700.271 Info from server: Processed 3 Failed 0 Total 3 Seconds spent 0.000048
  1214:20110127:011700.272 OK
  1214:20110127:011700.273 End of send_buffer():SUCCEED
  1214:20110127:011700.274 Buffer: new element 0
  1214:20110127:011700.285 For key [net.tcp.service[ssh,,8022]] received value [1]
  1214:20110127:011700.286 In process_value() key:'xxxx-xxxxxxxxxxx:net.tcp.service[ssh,,8022]' value:'1'
  1214:20110127:011700.287 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:1/100
  1214:20110127:011700.287 Will not send now. Now 1296083820 lastsent 1296083819 < 30
  1214:20110127:011700.288 End of send_buffer():SUCCEED
  1214:20110127:011700.288 Buffer: new element 1
  1214:20110127:011700.353 For key [proc.num[dropbear]] received value [1]
  1214:20110127:011700.354 In process_value() key:'xxxx-xxxxxxxxxxx:proc.num[dropbear]' value:'1'
  1214:20110127:011700.354 In send_buffer() host:'x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171' port:10051 values:2/100
  1214:20110127:011700.355 Will not send now. Now 1296083820 lastsent 1296083819 < 30
  1214:20110127:011700.356 End of send_buffer():SUCCEED

Предположения:
С момента пропадания связи агент более 15 минут ожидал получение данных по датчику:

  1214:20110127:011659.422 For key [net.tcp.service.perf[http, www.google.com, 80]] received value [919.496813]

Возможно предположить, что значения снимаются в ОДНОМ потоке/дочернем процессе, и данный датчик блокировал все остальные. Но тогда каким образом проскочил опрос данного датчика до истечения таймаута предыдущего? И почему таймаут не сработал?

  1214:20110127:010139.917 TCP expect network error: Cannot connect to [[172.20.1.251]:80] [Network is unreachable]
  1214:20110127:010139.917 For key [net.tcp.service.perf[http, 172.20.1.251, 80]] received value [0.000000]

Не понятно, что может быть. Возможно взаимная блокировка...

Агент 1.8.3, сервер 1.8.4, платформа с обоих сторон линуксоподобная. Конфиг агента:

DebugLevel=4
LogFile=/tmp/zabbix_agentd.log
LogFileSize=1
AllowRoot=1
EnableRemoteCommands=1
LogRemoteCommands=1
Server=x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171
DisablePassive=1
DisableActive=0
RefreshActiveChecks=120
BufferSend=30
StartAgents=3
SourceIP=172.22.83.46

[dima_dm]

Я думаю, Вам стоит поскать причину проблемы так

http://www.zabbix.com/forum/showthread.php?t=18597

Т.к. у вас Linux, используйте утилиты strace и ltrace, tcpdump

[mkolomiets]

Я думаю, Вам стоит поскать причину проблемы так

http://www.zabbix.com/forum/showthread.php?t=18597

Т.к. у вас Linux, используйте утилиты strace и ltrace, tcpdump

Да я читал этот пост, попробую. Хотя проблематично будет словить момент, так как возникает ситуация произвольно, да и ресурсы железа не позволяют сильно развернуться.

Вот еще подобная ситуация - но тут возврат из refresh_active_checks так и не наступил, в таких случаях помогает только рестарт агента.

  1214:20110127:045725.107 In check_response({
	"response":"success",
	"info":"Processed 4 Failed 0 Total 4 Seconds spent 0.000049"})
  1214:20110127:045725.107 Info from server: Processed 4 Failed 0 Total 4 Seconds spent 0.000049
  1214:20110127:045725.108 OK
  1214:20110127:045725.109 End of send_buffer():SUCCEED
  1214:20110127:045725.110 refresh_active_checks('x.x.x.170,x.x.x.227,x.x.x.226,x.x.x.171',10051)
  1214:20110127:045725.310 Sending [{
	"request":"active checks",
	"host":"xxxx-xxxxxxxxxxx"}]
  1214:20110127:045725.311 Before read
  1213:20110127:045747.279 In collector_diskdevice_get("")
  1213:20110127:045847.550 In collector_diskdevice_get("")
  1213:20110127:045947.823 In collector_diskdevice_get("")
  1213:20110127:050048.140 In collector_diskdevice_get("")
  1213:20110127:050148.402 In collector_diskdevice_get("")
  1213:20110127:050248.799 In collector_diskdevice_get("")
  1213:20110127:050349.057 In collector_diskdevice_get("")
  1213:20110127:050449.392 In collector_diskdevice_get("")
  1213:20110127:050549.659 In collector_diskdevice_get("")
[COLOR="red"]И так до самого конца...[/COLOR]

[dima_dm]

Если не удасться найти причину, можно использовать workaround.
Т.е. проверять работу zabbix_agentd из root cron, и если он не работает, перезапускать его. Но лучше, конечно, понять причину.

[mkolomiets]

Если не удасться найти причину, можно использовать workaround.
Т.е. проверять работу zabbix_agentd из root cron, и если он не работает, перезапускать его. Но лучше, конечно, понять причину.

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

[mkolomiets]

Дошли руки поковырятся в проблеме, и вот что удалось выяснить на данный момент:
В методе refresh_active_checks в параметр timeout для zbx_tcp_recv_ext передается жестко прописанное значение "0", которое в свою очередь прописывается в параметрах сокета.

if (SUCCEED == (ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE, [B][I]0[/I][/B])))

Значение 0 в данном контексте подразумевает то, что таймаут операций с сокетом никогда не наступит. Вот и выходит что при пропадании связи в момент между отправкой запроса и получением перечня ключей с сервера, агент будет ждать до посинения.

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

if (SUCCEED == (ret = zbx_tcp_connect(&s, CONFIG_SOURCE_IP, host, port, [B][I]CONFIG_TIMEOUT[/I][/B])))

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

[asaveljevs]

Это очень печально, но это был баг. За последние несколько недель мы исправили несколько проблем с таймаутами (например, ZBX-2913, ZBX-3446 и ZBX-3479), в том числе и эту. В последней ревизии бранча 1.8 (и в предстоящем 1.8.5) такой проблемы уже не должно быть.

[mkolomiets]

Привет!

Это очень печально, но это был баг. За последние несколько недель мы исправили несколько проблем с таймаутами (например, zbx-2913, zbx-3446 и zbx-3479), в том числе и эту. В последней ревизии бранча 1.8 (и в предстоящем 1.8.5) такой проблемы уже не должно быть.

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

Спасибо за ответ!
Кста, и за ссылки на багрепорты тоже спасибо, надо глянуть - может я еще где то велосипед изобретаю.

[zalex_ua]

Спасибо за ответ!

Моих 5 копеек тут тоже есть , цитирую с IRC лог:

[18.02.2011 13:58] * zalex_ua * richlv, it's a gud question for devs (last thread post) http://www.zabbix.com/forum/showthread.php?t=20741 
[18.02.2011 14:25] * Richlv * zalex_ua, asaveljevs responded ;)

[mkolomiets]

Привет!

Моих 5 копеек тут тоже есть , цитирую с irc лог:

Спасибо!

ЗЫ. Гуртом і батька легше бити!

[mkolomiets]

Продолжаю ловить пропущенные ограничения по таймауту

Кому нужно - патч для 1.8.4 агента, это то что пока успел найти - получение списка счетчиков и отправка данных на сервер, несколько мест в проверке net.tcp.service.perf.
ЗЫ. пользую агентов только в активном режиме, может для пассивного что то и упустил.

[zalex_ua]

Кому нужно - патч для 1.8.4 агента

Посмотрел исходники в репозитарии. По файлу simple.c похоже все учтено уже, хотя я не очень внимательно всматривался.
А по файлу active.c - посмотрел только начало и вижу что нету таких изменений.
Рекомендую вникнуть и самостоятельно опубликовать на трекере запрос.