[ZBX-19029] Missing lastlogsize information - ZABBIX SUPPORT

XML

Word

Printable

Details

Type: Problem report
Status: Closed
Priority: Critical
Resolution: Fixed
Affects Version/s: 5.0.8
Fix Version/s: 5.0.9rc2, 5.2.5rc2, 5.4.0alpha2, 5.4 (plan)
Component/s: Proxy (P), Server (S)
Labels:
- log
- preprocessing
- proxy

Team:
Team A
Sprint:
Sprint 73 (Feb 2021)
Story Points:
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

Assignee:: Vladislavs Sokurenko

Reporter:: Alexey Pustovalov

Votes:: 0 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2021 Feb 16 19:56

Updated:: 2021 Nov 16 08:56

Resolved:: 2021 Feb 19 10:02