-
Problem report
-
Resolution: Fixed
-
Critical
-
5.0.8
-
Sprint 73 (Feb 2021)
-
1
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.
