Event deletion job does not work

Bharath Kumar shared this problem 2 weeks ago
Awaiting Reply

Hi,

We have set the job on event and event archive table following the below:

INSERT INTO Configuration VALUES (1, ‘SYSTEM’, ‘EVENTMAXDAYS’, 1)

INSERT INTO Configuration VALUES (1, ‘SYSTEM’, ‘EVENTARCHIVEMAXDAYS’, 1)

We have set this job for all the client orgs in our database. But I see this job is not working and is not cleaning up the old records in the event table.

When I see the task schedule for the status of the event archive job, it says status failed:

FAILURE;com.microsoft.sqlserver.jdbc.SQLServerException: socket closed;0;NULL;NULL;NULL

Can you please provide some solution how to configure to make this job working.

Regards,

Bharath

Comments (17)

photo
1

Hi Bharath,

Because of the "socket closed" exception I'm wondering whether the connection to the SmartReporting configuration database is timing out. So going along this line of thought could you please add the JDBCTimeout parameter to your web.xml file and give it a high value (e.g. 1 hour) as described in the following Knowledge Base article:

https://community.yellowfinbi.com/knowledge-base/article/how-to-increase-the-connection-timeout-to-the-yellowfin-database

(and then don't forget to restart SmartReporting)

Please let me know whether this helps or not.

regards,

David

photo
1

Hi Dave,

Thanks for the response. We already have the jdbc timeout as 3600.

Regards,

Bharath

photo
1

Hi Bharath,

OK, that should easily be enough time.

I decided to test this out on a BMC build of Yellowfin 7.3 and it worked for me (unfortunately! I would have been very happy if I got an Exception like you)

See below, you can see that the EventArchiveTask last ran at '20180510022600' (that is in GMT) and the system time was 12:28 (in GMT that's '20180510022800'),

thus it had just run 2 minutes prior to the screenshot, and you can see that the LastRunStatus was "SUCCESS"

/AbP26WwVPWeDAAAAAElFTkSuQmCCAA==

and then I checked the Event table and it only contained today's events, which is the expected result.

Anyway, that's where my investigation is at the moment.

Could you please tell me exactly which build of 7.3 you are using?

And also please send across the SmartReporting.log file (the application log)

thanks,

David

photo
1

Hello again Bharath,

actually, just to play it safe, could you please send across all the logs from the logs folder.

thanks,

David

photo
1

Sure Dave, I will get the logs.

photo
1

great, thanks!

photo
1

Hi Dave,

Attached the info.jsp file and the logs.

Thanks in advance!

Regards,

Bharath

photo
1

Hi Bharath,

thanks for the logs, there are lots of errors in them, and so to help me pinpoint which are relevant to the issue at hand could you please tell me whether you manually ran the Event deletion job, and if so, what time did you run it?

Otherwise, if you didn't manually run it, then please tell me what time it is configured to regularly run. You can find out this information by running the following query:


SELECT * 
FROM TaskSchedule 
WHERE ScheduleUnitCode = 'EventArchiveTask'
thanks,

David

photo
1

Hi Dave,


Can you please check the attachment of the whole TaskSchedule output in excel.

We tried to run manual deletion once a day, when I came to work around 8 AM.

Regards,

Bharath

photo
1

Hi Bharath,

thanks for the information, I can see that your EventArchiveTask is configured to run daily at 15:34:48 which is GMT, so when converted to your timezone (GMT - 7) that becomes 8:34 AM.

But unfortunately when I look through the smartreporting.log files from 8:21 AM (because that's what time the oldest log file starts, "smartreporting.log.9") up to 9 AM

the only error I can see is:

Error occurred when connecting to the database: java.lang.Exception: Source AR System is marked as unavailable

which is nothing to do with the Event Deletion Job issue, as you would know, SmartReporting does not need to connect to the Source AR System to move and delete records in the SmartReporting configuration database, instead it needs to connect to the ARReport database.


Also, the log file called jdbc.log is the specific log file for connections to the Smart Reporting configuration database and it shows no errors at all around the time of 8 AM:

2018-05-14 05:41:59   INFO: Connection[10] successfully reopened
2018-05-14 08:11:00   INFO: Created Connection[12]
2018-05-14 09:17:00   INFO: Connection[0] has been open for 4 h, 521 ms and will be recycled
This means that unfortunately there was nothing to help my investigation in that set of logs.


However, just out of interest I looked at the source code for the class which is responsible for deleting the Event Archive records and I saw in the constructor the following lines:

   public EventArchiveTask(TaskScheduleBean tsb) {
      log.debug("Entering EventArchiveTask");
and then further on in the class were also the following lines:

         log.debug("Max days in Event table: " + eventMaxDays);
         log.debug("Max days in EventArchive table: " + eventArchiveMaxDays);
so this definitely means that if you change your logging level to DEBUG just for the EventArchiveTask class during the period when the EventArchiveTask runs then we should at least see the first of the above entries in the debug log file.

The way to do this is to add the following line to your log4j.properties file (<smartreporting>\appserver\webapps\ROOT\WEB-INF):


log4j.category.com.hof.servlet.EventArchiveTask=DEBUG


I have just tested this out over here and it worked fine for me, here are the entries in the yellowfin.log after the EventArchiveTask ran:


YF:2018-05-16 16:27:00: INFO (LicenceCheckProcess:checkDataSource) - DataSources: 1
YF:2018-05-16 16:27:00: INFO (LicenceCheckProcess:checkDataSource) - Primary Org DataSources: 1
YF:2018-05-16 16:27:00: INFO (LicenceCheckProcess:checkDataSource) - Client Org DataSources: 0
YF:2018-05-16 16:27:00: INFO (MIDataSourceEditAction:execute) - MIDataSourceEditAction exiting with action: MIAdminConsole
YF:2018-05-16 16:27:00: INFO (SystemTaskManager:run) - Instantiating class: EventArchiveTask
YF:2018-05-16 16:27:00: INFO (MIPreAdminConsoleAction:execute) - MIPreAdminConsoleAction entered
YF:2018-05-16 16:27:00:DEBUG (EventArchiveTask:<init>) - Entering EventArchiveTask
YF:2018-05-16 16:27:00:DEBUG (EventArchiveTask:<init>) - Max days in Event table: 1
YF:2018-05-16 16:27:00:DEBUG (EventArchiveTask:<init>) - Max days in EventArchive table: 1
YF:2018-05-16 16:27:00: INFO (MIPreAdminConsoleAction:execute) - MIPreAdminConsoleAction exiting
YF:2018-05-16 16:27:01: INFO (ColourPickerAjaxAction:runAction) - ColourPickerAjaxAction entered
YF:2018-05-16 16:27:01: INFO (MIAdminConsoleAjaxAction:runAction) - httpMethod -> GET
YF:2018-05-16 16:27:13: INFO (SystemTaskManager:run) - Success instantiating class: EventArchiveTask
YF:2018-05-16 16:27:13: INFO (SystemTaskManager:run) - Instantiating class: GroupFlattenTask
YF:2018-05-16 16:27:13: INFO (SystemTaskManager:run) - Success instantiating class: GroupFlattenTask


Incidentally, instead of waiting for 8 AM each day for the task to run, you can reconfigure the task to run every minute with the following query:


UPDATE TaskSchedule

SET FrequencyTypeCode = 'MINUTES',

FrequencyUnit = 1

WHERE ScheduleUnitCode = 'EventArchiveTask'


Having said that, I found that YF is checking the task table every 5 minutes, that means that shortest interval you can get the task to run is every 5 minutes (not every 1 minute)


Sorry this email is so long, but this investigation is proving difficult, hopefully your new debug logging for the EventArchiveTask class will give us something to go on.


regards,

David

photo
1

Thanks a Lot David. I will get back to you with the event archive debug logs.

Regards,

Bharath

photo
1

great! I await the debug logs...

photo
1

Hi Dave,

I’ve changed the database with command:

UPDATE TaskSchedule

SET FrequencyTypeCode = 'MINUTES',

FrequencyUnit = 1

WHERE ScheduleUnitCode = 'EventArchiveTask'

And I can see in the smartreporting.log Line 102:

BMC:SR:2018-05-18 09:47:48: INFO (LogonAction:execute) - Logon Action entered

BMC:SR:2018-05-18 09:47:48: INFO (LogonAction:performLogin) - Internal Entry Point for Logon

BMC:SR:2018-05-18 09:47:48: INFO (LogonAction:performLogin) - logon authorised..

BMC:SR:2018-05-18 09:49:00:DEBUG (EventArchiveTask:<init>) - Entering EventArchiveTask

BMC:SR:2018-05-18 09:49:00:DEBUG (EventArchiveTask:<init>) - Max days in Event table: 1

BMC:SR:2018-05-18 09:49:00:DEBUG (EventArchiveTask:<init>) - Max days in EventArchive table: 1

I’ve also attached the logs folder from today, after the database update and restarting for Smart Reporting servie.

Let me know if it helps.

Regards,

Bharath

photo
1

Hi Bharath,

thanks for doing that, I've looked through all the logs and the strange thing is that I can't see anything in the logs that would indicate something has gone wrong with the EventArchiveTask.

As you pointed out, there there are no errors in the smartreporting debug log, and there are also no errors around the same time (2018-05-18 09:49:00) in the JDBC log which is the log file that records information about connections to the ARReport database:

2018-05-18 09:46:10   INFO: Created Connection[7]
2018-05-18 09:47:00   INFO: Created Connection[8]
2018-05-18 09:51:00   INFO: Created Connection[9]
2018-05-18 09:55:00   INFO: Created Connection[10]
2018-05-18 10:03:00   INFO: Created Connection[11]
2018-05-18 10:04:00   INFO: Created Connection[12]
However there is still one more thing we can look, sorry I didn't notice it earlier but I just noticed now that SmartReporting creates an entry in the Event table when the EventArchive job runs, I just ran mine now and here is the EventData column from the relevant Event record:


EventMaxDays=1,EventArchiveMaxDays=30,EventsArchived=58,ArchivedEventsDeleted=17,Duration=25ms
So could you please run the following query and send across the results:


select * from event where eventcode = 'EVENTARCHIVE'

Also, I'm still wondering the problem is actually that SQL Server is closing the connection itself and therefore your DBA needs to re-configure the database to stop this situation.

Is there anything in SQL Server's audit logs abou the "Socket Closed" error?


regards,

David

photo
1

Hi David,

Here is the result of select*fromeventwhere eventcode ='EVENTARCHIVE'

I’ve talked to dba, and they haven’t found any socket closed error in any log for the past 7 days.

Regards,

Bharath

photo
1

Hi Bharath,

thanks for the Event data, and the most recent entry in it is from "2018-05-22 10:59:00" (GMT) and shows the following:

EventsArchived=163ArchivedEventsDeleted=163Duration=68ms

which means it was successful.

and in fact, every entry before it (I see they are running every 5 minutes) was successful.

This is a very strange state of affairs. So far what we've learned is:


1) In the Schedule Manager the EventArchiveTask shows a FAILURE with the error "com.microsoft.sqlserver.jdbc.SQLServerException: socket closed"

2) In the smartreporting log and also the jdbc log there are no corresponding errors.

3) In the Event table the job is recorded as having worked correctly.

4) your DBA says that there isn't anything on his end that indicates the DBMS closed the socket.


I'm going to have to ask someone cleverer than me about this if you can please bear with me, hopefully I'll be able to get back to you in a day.

regards,

David

photo
1

Hello again Bharath,

actually, before I do that I've just thought of something else.

I noticed in your JDBC log that you have "Verify Connections" turned off. Therefore I think it would be well worth it to turn it on and see if that resolves the issue.

The following Knowledge Base article explains how to do this:

https://community.yellowfinbi.com/knowledge-base/article/jdbc-verify

Please let me know how it goes.

regards,

David