search

woocommerce / action-scheduler-custom-tables

This plugin is no longer needed. The custom table code is now part of Action Scheduler version 3.0 and newer. If you're using the latest Action Scheduler, you have the most performant schema available.
https://actionscheduler.org
14 stars 2 forks source link

Log entries displayed on list table always show current time #45

Closed thenbrent closed 5 years ago

thenbrent commented 6 years ago

Note: this was initially opened in AS repo with https://github.com/Prospress/action-scheduler/issues/178, but I'm 90% sure it's related only to custom tables now, so I'm opening it here instead.

The date/time displayed against log entries on the admin list table always show current time, not the time of the actual events.

For example, here are the log events displayed for the same scheduled action on the admin page loaded about 10 minutes apart:

  1. Load at 2018-07-17 04:29:15 UTC: https://cl.ly/3p0V0u430s2b
  2. Load at 2018-07-17 04:38:43 UTC: https://cl.ly/0T1I0r1y0o1t

Notice the times display on each change depending on the page load time, and all entries display the times the page was loaded.

I noticed this on ticket https://secure.helpscout.net/conversation/555708450/7375?folderId=1524436

I've also seen it on other sites.

thenbrent commented 6 years ago

What I think is happening here is that the log entries are being deleted from the source data store (i.e. ActionScheduler_wpPostStore) before the migration of them begins, because:

  1. Migration_Runner::migrate_actions() calls Action_Migrator::migrate() before it calls Log_Migrator::migrate(), and
  2. Action_Migrator::migrate() calls $this->source->delete_action(), meaning delete_action() is called before Log_Migrator::migrate(), however
  3. ActionScheduler_wpPostStore::delete_action() calls wp_delete_post(), which also deletes all comments (which is where log entries are stored).

The gotcha is that because Action_Migrator::migrate() uses standard action APIs on the new data store, the log entries are created in the new data store, only they are created for the time the action is migrated, not the original times. That's why the dates end up all being the same.

This also explains why it wasn't reproducible, and was apparently intermittent. It only effects migrated actions.

There's a few ways we can fix it. The fix will need to both:

  1. make sure the original logs are migrated, likely by getting them before the action is deleted; and
  2. make sure the created etc. logs are not added when migrating the action - we already have a specific log for that
thenbrent commented 6 years ago

Importantly, the above theory doesn't explain this:

Notice the times display on each change depending on the page load time, and all entries display the times the page was loaded.

That's a separate issue. Fortunately, I think I also found the source of that - ActionScheduler_LogEntry is being instantiated without passing the 3rd $date param, which is the source of the log entry's display date.