Opcle process taking long to get that log was rolled

  • KM03770070
  • 28-Dec-2020
  • 28-Dec-2020

Summary

the process takes 21 intervals to get that log was rolled.

Error

Opcle policy configured to read a test.log, when the log is rolled and a new one is created it takes 21 intervals for the policy to get that log was rolled, close the old log and open the new one to read it.

If polling interval is set to 2 minutes, then it takes 42 minutes to get the change.

After that time, an event is received:

Logfile /tmp/logs/test.log was removed and re-created but 'close' option is off. Reopening the file. (OpC30-133)

And the new log is read.

How to reproduce it:

  • Create an opcle to read a test.log, Read mode is “Read from last position” and “Close after reading” is NOT checked,  and deploy it to a node.
  • Add data to the log that matches the policy, it should create an event when opcle reads it.
  • Before the next time opcle reads it (based on the polling interval), add more data that matches the policy to the test.log, rename/move the test.log to another file, for example, test_0001.log, and create a new  test.log with data that should match the policy
  • According to the documentation, if “Close after reading” is NOT checked, opcle should read the new lines in the old log (test_0001.log), then close it, open and read the new test.log, but it doesn’t happen, it just reads the old test_0001.log and after 21 times opcle reads the log, it got that log was rolled and do the change.

 

From trace file:

opcle(8808:8808)[debug]: LE: Check procedure called for object /tmp/test.log --> Checking the log

opcle(8808:8808)[debug]: LE: Getting status of lfile /tmp/test.log (fd = 10)

opcle(8808:8808)[debug]: LE: Status 121 1608222354

opcle(8808:8808)[debug]: LE: Ino = 260629 --> Get the current inode, at chis point the inode is from the rolled log.

opcle(8808:8808)[int]: /tmp/logs/test.log: mtimes 1608222354/1608222354 not changed

            …

            …

opcle(8808:8808)[debug]: LE: Logfile /tmp/test.log 21 times not changed --> It noticed that log was read 20 times without any change and re-check the logfile name.

opcle(8808:8808)[debug]: LE: Getting status of lfile /tmp/test.log (fd = -1)

opcle(8808:8808)[debug]: LE: remove_quotes: Returning /tmp/test.log

opcle(8808:8808)[debug]: LE: Status 51 1608222354

opcle(8808:8808)[debug]: LE: Ino = 260628 --> As the log was rolled, the inode change, here it gets the new inode and generated the event.

opcle (8808:8808)[debug]: ERRLIST: [../genle.c:7586]: Logfile /tmp/test.log was removed and re-created but 'close' option is off. Reopening the file. (OpC30-133) (Errorcode:1966213)

 

Cause

By default opcle check for the change in file name and inode after 20 intervals only.

Fix

It can be  configured using the following configuration option.

 

OPC_LE_CHECK_INODE

Description : Sets the interval when a file name change is recognized by the logfile encapsulator

Type/Unit : integer

Default : 20

Restart required: Y

 

/opt/OV/bin/ovconfchg -ns eaagt -set OPC_LE_CHECK_INODE <value>

/opt/OV/bin/ovc -restart opcle

 

The <value> would be the number of intervals needed to check the log name change, if it is set to 1 and polling interval is 2 minutes, it would take 4 minutes to notice the change of the log.