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

Missing lastlogsize information

    XMLWordPrintable

Details

    • Team A
    • Sprint 73 (Feb 2021)
    • 1

    Description

      When logrt[/tmp/test.log,,,,skip,,,mtime-noreread] log item has JavaScript processing step like:

      var test = /555|666/;
      if (test.test(value)) {return null;}
      return value;
      

      Fields lastlogsize and mtime are not updated independent of result (new value or only metadata come).

      Item without processing step:
      agent log (active checks):

       2759:20210216:124659.529 In send_buffer() host:'zabbix-proxy-sqlite3' port:10051 entries:1/100
        2759:20210216:124659.529 JSON before sending [{"request":"agent data","session":"e8e4a10ad342f6f361a85a14f8df1383","data":[{"host":"zabbix_test","key":"logrt[/tmp/test.log,,,,skip,,,mtime-noreread]","value":"Tue Feb 16 12:46:54 EST 2021","lastlogsize":29,"mtime":1613497614,"id":9,"clock":1613497619,"ns":528956564}],"clock":1613497619,"ns":529549373}]
        2759:20210216:124659.529 JSON back [{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000087"}]
        2759:20210216:124659.529 In check_response() response:'{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000087"}'
      

      proxy log (history syncer):

         156:20210216:124700.526 In zbx_sync_history_cache() history_num:1
         156:20210216:124700.526 query [txnlev:1] [begin;]
         156:20210216:124700.526 In DCmass_proxy_add_history()
         156:20210216:124700.526 query [txnlev:1] [insert into proxy_history (itemid,clock,ns,timestamp,source,severity,value,logeventid,lastlogsize,mtime,flags,write_clock) values (32653,1613497619,528956564,0,'',0,'Tue Feb 16 12:46:54 EST 2021',0,29,1613497614,1,1613497620);
      ]
         159:20210216:124700.526 zbx_setproctitle() title:'history syncer #4 [processed 0 values in 0.000125 sec, syncing history]'
         159:20210216:124700.526 In zbx_sync_history_cache() history_num:1
         159:20210216:124700.526 zbx_setproctitle() title:'history syncer #4 [processed 0 values in 0.000082 sec, idle 1 sec]'
         158:20210216:124700.526 zbx_setproctitle() title:'history syncer #3 [processed 0 values in 0.000185 sec, syncing history]'
         158:20210216:124700.526 In zbx_sync_history_cache() history_num:1
         158:20210216:124700.526 zbx_setproctitle() title:'history syncer #3 [processed 0 values in 0.000033 sec, idle 1 sec]'
         156:20210216:124700.526 End of DCmass_proxy_add_history()
         156:20210216:124700.526 In DCmass_proxy_update_items()
         156:20210216:124700.526 query [txnlev:1] [update item_rtdata set lastlogsize=29,mtime=1613497614 where itemid=32653;
      ]
         156:20210216:124700.526 End of DCmass_proxy_update_items()
      

      Proxy DB:

      sqlite> select * from item_rtdata;
      32653|29|0|1613497614|
      sqlite> select * from proxy_history;
      8|32653|1613497619|0||0|Tue Feb 16 12:46:54 EST 2021|0|528956564|0|29|1613497614|1|1613497620
      

      Then processing step added. Sending values "test555test" and "test" (first one must be ignored):
      agent log:

        2759:20210216:125259.690 End of need_meta_update():FAIL
        2759:20210216:125259.690 In send_buffer() host:'zabbix-proxy-sqlite3' port:10051 entries:1/100
        2759:20210216:125259.691 JSON before sending [{"request":"agent data","session":"e8e4a10ad342f6f361a85a14f8df1383","data":[{"host":"zabbix_test","key":"logrt[/tmp/test.log,,,,skip,,,mtime-noreread]","value":"test555test","lastlogsize":41,"mtime":1613497960,"id":10,"clock":1613497979,"ns":690608163}],"clock":1613497979,"ns":691148160}]
        2759:20210216:125259.691 JSON back [{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000118"}]
        2759:20210216:125259.691 In check_response() response:'{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000118"}'
        2759:20210216:125259.691 info from server: 'processed: 1; failed: 0; total: 1; seconds spent: 0.000118'
      ....
        2759:20210216:125459.746 In send_buffer() host:'zabbix-proxy-sqlite3' port:10051 entries:1/100
        2759:20210216:125459.746 JSON before sending [{"request":"agent data","session":"e8e4a10ad342f6f361a85a14f8df1383","data":[{"host":"zabbix_test","key":"logrt[/tmp/test.log,,,,skip,,,mtime-noreread]","value":"test","lastlogsize":46,"mtime":1613498073,"id":11,"clock":1613498099,"ns":746200933}],"clock":1613498099,"ns":746754628}]
        2759:20210216:125459.747 JSON back [{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000109"}]
        2759:20210216:125459.747 In check_response() response:'{"response":"success","info":"processed: 1; failed: 0; total: 1; seconds spent: 0.000109"}'
        2759:20210216:125459.747 info from server: 'processed: 1; failed: 0; total: 1; seconds spent: 0.000109'
      

      proxy log:

         157:20210216:125300.687 In zbx_sync_history_cache() history_num:1
         157:20210216:125300.687 query [txnlev:1] [begin;]
         157:20210216:125300.687 In DCmass_proxy_add_history()
         157:20210216:125300.687 query [txnlev:1] [insert into proxy_history (itemid,clock,ns,value,flags,write_clock) values (32653,1613497979,690608163,'',2,1613497980);
      ]
         157:20210216:125300.688 End of DCmass_proxy_add_history()
      ...
         157:20210216:125500.743 In DCmass_proxy_add_history()
         157:20210216:125500.743 query [txnlev:1] [insert into proxy_history (itemid,clock,ns,timestamp,source,severity,value,logeventid,lastlogsize,mtime,flags,write_clock) values (32653,1613498099,746200933,0,'',0,'test',0,0,0,0,1613498100);
      ]
         157:20210216:125500.743 End of DCmass_proxy_add_history()
         157:20210216:125500.743 In DCmass_proxy_update_items()
         157:20210216:125500.743 End of DCmass_proxy_update_items()
         157:20210216:125500.743 query [txnlev:1] [commit;]
         157:20210216:125500.744 zbx_setproctitle() title:'history syncer #2 [processed 1 values in 0.001067 sec, idle 1 sec]'
      

      Proxy DB:

      sqlite> select * from item_rtdata;
      32653|29|0|1613497614|
      sqlite> select * from proxy_history;
      8|32653|1613497619|0||0|Tue Feb 16 12:46:54 EST 2021|0|528956564|0|29|1613497614|1|1613497620
      9|32653|1613497979|0||0||0|690608163|0|0|0|2|1613497980
      ...
      sqlite> select * from item_rtdata;
      32653|29|0|1613497614|
      sqlite> select * from proxy_history;
      8|32653|1613497619|0||0|Tue Feb 16 12:46:54 EST 2021|0|528956564|0|29|1613497614|1|1613497620
      9|32653|1613497979|0||0||0|690608163|0|0|0|2|1613497980
      10|32653|1613498099|0||0|test|0|746200933|0|0|0|0|1613498100
      

      So when such JavaScript processing is added, it does not matter value is filtered out or not, rttdata is not updated anymore.

      Attachments

        Activity

          People

            vso Vladislavs Sokurenko
            dotneft Alexey Pustovalov
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: