Uploaded image for project: 'ZABBIX BUGS AND ISSUES'
  1. ZABBIX BUGS AND ISSUES
  2. ZBX-15704

Agent log item may send meta information without obvious needs

    Details

    • Team:
      Team C
    • Sprint:
      Sprint 51 (Apr 2019)
    • Story Points:
      2

      Description

      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.

        Attachments

          Activity

            People

            • Assignee:
              asestakovs Aleksejs Sestakovs
              Reporter:
              zalex_ua Oleksiy Zagorskyi
            • Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: