No monthly log entry made at end of day

[billy]

My monthly log updates at 5 minute intervals. Since earlier this month it is missing an entry for 9 am - ie the end of day rollover time. No other entries seem to be missing. realtime.txt is also not updated at 9 am (but is at 08:59 and 09:01). Again, no other entry seems to be missed. An appropriate entry into dayfile.txt has been made on all these days. I have debug logging on and there is nothing obvious in the log - at least to my somewhat naive eyes. For the past month or so, I have made a lot of changes - all related to installing new website styles (cumulus utils and mx ui).

I'd be grateful for any clues to where I should be looking to resolve this.

[mcrossley]

First thing is for me to start looking into it. But meantime could you capture an MXdiags log over the rollover period with debug logging switch on please?

Edit: Actually I can see there may be a problem *if* your end of day processing takes longer than 1 minute.

[billy]

Attached is the log for the first 9 days of this month. The monthly log's 9 am record was added from 1st- 6th (as is normal) then has been omitted every day since starting June 7. I have three mysql uploads - dayfile, monthly and realtime (a custom one at 1 minute interval). In one sense this is a trivial problem but in another sense, I am pretty certain I have changed something to cause this! And of course I have not kept a good log of my changes

[mcrossley]

OK, so the problem *is* that the rollover is taking longer than one minute.

Up to the 6th, everything was OK.

On the 6th the insert into the MySQL failed but took 40 seconds to fail, so the EOD processing then continued and ended within the minute.

But from the 7th onwards the MySQL insert is taking over a minute to timeout, so the time is then 09:01 when MX checks if it is time to write to the log file - which is a simple is the current minute a multiple of the configured interval.

So the MX code needs fixing to avoid that situation.
But meantime you need to look into why the inserts into the Dayfile MySQL table are taking so long.

[freddie]

A suggestion - you could do the dayfile write first and then all the other stuff after? It would protect the integrity of the internal data writes from external influences such as slow SQL inserts.

[mcrossley]

I think I'll make the SQL calls asynchronous - some are done before the EOD processing and the default call is in the middle of it.

[billy]

Mark , many thanks for directing me to the cause. The reason for the MySQL failure is not the insert itself, but a trigger set to run after the insert. I stopped the trigger this morning and the monthly log entry proceeded smoothly and quickly as it had done before these problems arose. The trigger was for some very inefficient MySQL code but I had assumed - incorrectly - it would not interfere with other cumulus activity associated with the end of the day.

I see you have already provided an MX update to make the MySQL inserts asynchronous - that's really quick service, that I really appreciate. I will install it now, re-institute the trigger, and see what happens tomorrow morning. There is plenty of room to improve the efficiency of the trigger.

I hadn't picked up that the MySQL insert was failing, but realized it can be detected by the absence of the message "MySQL: 1 rows were affected". I presume that's how you noticed the problem?

[mcrossley]

I hadn't picked up that the MySQL insert was failing, but realized it can be detected by the absence of the message "MySQL: 1 rows were affected". I presume that's how you noticed the problem?

Well, that and the MySQL connection failed message

[billy]

Well, that and the MySQL connection failed message

Well I had ignored those because there were MySQL error messages on the 6June rollover and that worked - well just I will look more carefully in future