4.4.3 - log[] is reading the same lines twice

[HaveDill]

For some reason my zabbix agent appears to be reading the same lines twice. It grabs only the newest values (so it's not like it's reading from the start of file), but logs them twice. Sadly because of the ordering, preprocessing to remove duplicate data does not work


It's a very simple item, and i've used log items in the past a lot. First time i've seen this type of issue. I have it set to read the log once every 5 minutes. As you can see, it grabbed the two newest lines, but did it twice.

[andris]

You can try DebugLevel=4 in zabbix_agentd to see how the log file looks from the agent view. It is sensitive to modification time, size, inode number, md5 sum of the initial block.

[HaveDill]

Here's the logs from an event i posted. I trimmed it to make it more human readable. Note this file gets written to only a couple times per day.

In this specific case, i do NOT timestamp my log lines. It's reading a json value for a zabbix discovery process.

https://imgur.com/a/CWvYnxz

 31819:20200103:100418.344 got [{"response":"success","data": #########TRUNCATED############# {"key":"log[/tmp/zabbix_auditout.log]","delay":300,"lastlogsize":664878,"mtime":0}]}]
 31818:20200103:100418.347 got [{"response":"success","data":############TRUNCATED########## {"key":"log[/tmp/zabbix_auditout.log]","delay":300,"lastlogsize":664878,"mtime":0}]}]
31819:20200103:100418.349 In add_check() key:'log[/tmp/zabbix_auditout.log]' refresh:300 lastlogsize:664878 mtime:0
 31818:20200103:100418.362 In add_check() key:'log[/tmp/zabbix_auditout.log]' refresh:300 lastlogsize:664878 mtime:0
31819:20200103:100618.508 got [{"response":"success","data":############TRUNCATED########## {"key":"log[/tmp/zabbix_auditout.log]","delay":300,"lastlogsize":664878,"mtime":0}]}]
 31818:20200103:100618.511 got [{"response":"success","data":############TRUNCATED######### {"key":"log[/tmp/zabbix_auditout.log]","delay":300,"lastlogsize":664878,"mtime":0}]}]
31819:20200103:100618.514 In add_check() key:'log[/tmp/zabbix_auditout.log]' refresh:300 lastlogsize:664878 mtime:0
 31818:20200103:100618.528 In add_check() key:'log[/tmp/zabbix_auditout.log]' refresh:300 lastlogsize:664878 mtime:0
 31819:20200103:100719.642 In process_logrt() flags:0x04 filename:'/tmp/zabbix_auditout.log' lastlogsize:664878 mtime:1578060643
 31819:20200103:100719.642 In add_logfile() filename:'/tmp/zabbix_auditout.log' mtime:1578067379 size:666710
 31819:20200103:100719.642 create_old2new_and_copy_of(): is_same_file(/tmp/zabbix_auditout.log, /tmp/zabbix_auditout.log) = 1
 31819:20200103:100719.642    nr:0 filename:'/tmp/zabbix_auditout.log' mtime:1578060643 size:665429 processed_size:664878 seq:1 copy_of:-1 incomplete:1 dev:64768 ino_hi:0 ino_lo:70896181 md5size:512 md5buf:bb40fd6b938ddd0a77bc63c6d3ff9347
 31819:20200103:100719.642    nr:0 filename:'/tmp/zabbix_auditout.log' mtime:1578067379 size:666710 processed_size:664878 seq:0 copy_of:-1 incomplete:0 dev:64768 ino_hi:0 ino_lo:70896181 md5size:512 md5buf:bb40fd6b938ddd0a77bc63c6d3ff9347
 31819:20200103:100719.642 In process_log() filename:'/tmp/zabbix_auditout.log' lastlogsize:664878 mtime:1578067379
 31819:20200103:100719.642 In process_value() key:'priv-vorl-util4:log[/tmp/zabbix_auditout.log]' lastlogsize:665430 value:'{"data":[{"GTS": ######### REDACTED #########]}'
 31819:20200103:100719.642 In process_value() key:'priv-vorl-util4:log[/tmp/zabbix_auditout.log]' lastlogsize:665804 value:'{"data":[{"GTS": ######### REDACTED #########"}}]}'
 31819:20200103:100719.642 End of process_log() filename:'/tmp/zabbix_auditout.log' lastlogsize:665804 mtime:1578067379 ret:SUCCEED processed_bytes:926
 31819:20200103:100719.642 In need_meta_update() key:log[/tmp/zabbix_auditout.log]
 31818:20200103:100719.657 In process_logrt() flags:0x04 filename:'/tmp/zabbix_auditout.log' lastlogsize:664878 mtime:1578060643
 31818:20200103:100719.657 In add_logfile() filename:'/tmp/zabbix_auditout.log' mtime:1578067379 size:666710
 31818:20200103:100719.657 create_old2new_and_copy_of(): is_same_file(/tmp/zabbix_auditout.log, /tmp/zabbix_auditout.log) = 1
 31818:20200103:100719.657    nr:0 filename:'/tmp/zabbix_auditout.log' mtime:1578060643 size:665429 processed_size:664878 seq:1 copy_of:-1 incomplete:1 dev:64768 ino_hi:0 ino_lo:70896181 md5size:512 md5buf:bb40fd6b938ddd0a77bc63c6d3ff9347
 31818:20200103:100719.657    nr:0 filename:'/tmp/zabbix_auditout.log' mtime:1578067379 size:666710 processed_size:664878 seq:0 copy_of:-1 incomplete:0 dev:64768 ino_hi:0 ino_lo:70896181 md5size:512 md5buf:bb40fd6b938ddd0a77bc63c6d3ff9347
 31818:20200103:100719.657 In process_log() filename:'/tmp/zabbix_auditout.log' lastlogsize:664878 mtime:1578067379
 31818:20200103:100719.657 In process_value() key:'priv-vorl-util4:log[/tmp/zabbix_auditout.log]' lastlogsize:665430 value:'{"data":[{"GTS": ######### REDACTED #########]}'
 31818:20200103:100719.657 In process_value() key:'priv-vorl-util4:log[/tmp/zabbix_auditout.log]' lastlogsize:665804 value:'{"data":[{"GTS": ######### REDACTED #########'
 31818:20200103:100719.657 End of process_log() filename:'/tmp/zabbix_auditout.log' lastlogsize:665804 mtime:1578067379 ret:SUCCEED processed_bytes:926

[HaveDill]

New interesting note,

Wrote a new line intraday today. Zabbix read the previous existing line, but did not read the new line i created. It's like it's not properly going to the EOF.

[gofree]

sometimes i had strange results when I was messing with contento of the log manually ( adding new lines ) , editing itemkeys ( especially when skip parameter was used ), etc ...item key for log monitoring can be very delicate from my experience

[HaveDill]

When i say i wrote a new line, i mean a python script i have fired off (manually) and wrote to the same log file. I generate a pretty large json value, then write it to file like this.

with open('/tmp/zabbix_auditout.log', 'a') as outfile:
            outfile.write('\n{"data":[')
            json.dump(zabbix_output, outfile)
            outfile.write(']}')

[gofree]

whtas the agent version, try to update it to the latest

[Markku]

In the python script above, it does not print a newline at the end, so do make sure that your test case is valid.

Markku

[HaveDill]

Tried what you mentioned, and swapped my newline character to the end of the write. Same issue still occurs. It's not a major issue for me, since the way i parse the output gives me the same results. Just annoying :/

[Yannick Croteau]

I Had this issue and I fixed it. In my case it was about the zabbix_agentd.conf. My ServerActive= has 2 entry for failed over. The first was my IP and second was my DNS. So the Active look to send the info to the both address. I just took off the DNS, and I've got just 1 line in my log now. I guess is because the active agent don't have syn-ack verification. Even with Zabbix 6.0 with native cluster possibility I have this kind of issue.

Support IT : Is it this behavior is normal?

[dimir]

Yes, it is designed behaviour of Zabbix agent. It does not perform any verification of the entries in ServerActive, it treats each entry as a separate instance.