-
Problem report
-
Resolution: Fixed
-
Major
-
4.0.4
-
Sprint 51 (Apr 2019)
-
2
Have a log[/tmp/aaa] item and fill the log file by a few lines in one go.
echo -e "Started-1\nFinished-1\nStarted-2\nFinished-2" >> /tmp/aaa
Agent will spot log file update and will send the firts line (see ZBX-9229) and later, here what happens in the debuglog:
18654:20190110:122009.309 In need_meta_update() key:log[/tmp/aaa] 18654:20190110:122009.309 End of need_meta_update():SUCCEED 18654:20190110:122009.309 In process_value() key:'it0:log[/tmp/aaa]' value:'(null)' 18654:20190110:122009.309 In send_buffer() host:'127.0.0.1' port:10051 entries:3/100 18654:20190110:122009.309 send_buffer() now:1547115609 lastsent:1547115609 now-lastsent:0 BufferSend:1; will not send now 18654:20190110:122009.309 End of send_buffer():SUCCEED 18654:20190110:122009.309 buffer: new element 3 18654:20190110:122009.309 End of process_value():SUCCEED 18654:20190110:122009.309 End of process_active_checks() 18654:20190110:122009.309 In get_min_nextcheck() 18654:20190110:122009.309 End of get_min_nextcheck():1547115610 18654:20190110:122009.309 __zbx_zbx_setproctitle() title:'active checks #1 [idle 1 sec]' 18650:20190110:122010.189 __zbx_zbx_setproctitle() title:'collector [processing data]' 18650:20190110:122010.189 In update_cpustats() 18650:20190110:122010.189 End of update_cpustats() 18650:20190110:122010.189 __zbx_zbx_setproctitle() title:'collector [idle 1 sec]' 18654:20190110:122010.309 In send_buffer() host:'127.0.0.1' port:10051 entries:4/100 18654:20190110:122010.310 JSON before sending [{"request":"agent data","session":"febb1670f21905dff57620de33b60d28","data":[{"host":"it0","key":"log[/tmp/aaa]","value":"Finished-1","lastlogsize":147,"id":17,"clock":1547115609,"ns":308704727},{"host":"it0","key":"log[/tmp/aaa]","value":"Started-2","lastlogsize":157,"id":18,"clock":1547115609,"ns":308916709},{"host":"it0","key":"log[/tmp/aaa]","value":"Finished-2","lastlogsize":168,"id":19,"clock":1547115609,"ns":309122137},{"host":"it0","key":"log[/tmp/aaa]","lastlogsize":168,"id":20,"clock":1547115609,"ns":309472514}],"clock":1547115610,"ns":310209522}] 18654:20190110:122010.310 JSON back [{"response":"success","info":"processed: 4; failed: 0; total: 4; seconds spent: 0.000264"}] 18654:20190110:122010.310 In check_response() response:'{"response":"success","info":"processed: 4; failed: 0; total: 4; seconds spent: 0.000264"}' 18654:20190110:122010.310 info from server: 'processed: 4; failed: 0; total: 4; seconds spent: 0.000264' 18654:20190110:122010.311 End of check_response():SUCCEED 18654:20190110:122010.311 OK 18654:20190110:122010.311 End of send_buffer():SUCCEED
note please how this meta information only (without "value":) was included (duplicated) without obvious needs:
{"host":"it0","key":"log[/tmp/aaa]","lastlogsize":168,"id":20,"clock":1547115609,"ns":309472514}
Here is related agent code:
if (0 != (ZBX_METRIC_FLAG_LOG & metric->flags))
{
/* meta information update is needed if: */
/* - lastlogsize or mtime changed since we last sent within this check */
/* - nothing was sent during this check and state changed from notsupported to normal */
/* - nothing was sent during this check and it's a new metric */
if (lastlogsize_sent != metric->lastlogsize || mtime_sent != metric->mtime ||
(lastlogsize_last == lastlogsize_sent && mtime_last == mtime_sent &&
(old_state != metric->state ||
0 != (ZBX_METRIC_FLAG_NEW & metric->flags))))
{
/* needs meta information update */
ret = SUCCEED;
}
}
I saw this issue many times when troubleshooted a server side issue with log monitoring.
Those cases were different and looking like even more strange, but I didn't write down steps to reproduce them. Hope a root cause is the same.
Something should be improved to avoid that.
