search

zencart / zencart

Zen Cart® is a full-function e-commerce application for your website.
https://github.com/zencart/zencart/releases
Other
375 stars 233 forks source link

zc_plugins getting uninstalled... #4014

Closed proseLA closed 1 year ago

proseLA commented 4 years ago

i am noticing during development that plugins are getting un-installed by ZC. i have tracked it down to:

https://github.com/zencart/zencart/blob/ace282f116e7d46467f43c97e45f5905e3c94440/admin/includes/application_bootstrap.php#L161

which i notice has been removed from v158; however it is getting called from here:

https://github.com/zencart/zencart/blob/aec59979d3c49da87151bf3fb9bdc6ef90d4d17d/laravel/app/Providers/AppServiceProvider.php#L39

why would cause ZC to automatically uninstall an already installed plugin?

proseLA commented 3 years ago

i'm thinking this is happening when a function within the plugin generates a 500 error. i will test when i have more time.

proseLA commented 3 years ago

i am still trying to track down why this happens.

on my development machine, an easy way to see it is to enable a plugin on a v157 branch; switch to a v156 branch; when you come back to the v157 branch, the plugin is disabled.

FAIK, this behavior is intended. i am still trying to determine when it happens in other cases.

drbyte commented 3 years ago

during development that plugins are getting un-installed by ZC. why would cause ZC to automatically uninstall an already installed plugin?

"uninstalled"

when you come back to the v157 branch, the plugin is disabled.

"disabled"

Are you using these words interchangeably? Or is more happening in one case vs the other?

proseLA commented 3 years ago

i apologize. i meant uninstalled in both cases.

however, i am now not able to reproduce the behavior that i thought i had witnessed.

during my development process i have commented out the $pluginManager->inspectAndUpdate(); line so as to not have my plugins uninstalled. but given that i can now not reproduce it from a switching of branches, please ignore that comment.

i will leave the line inspectAndUpdate in and more properly document and try to track down its behavior.

proseLA commented 3 years ago

ok, this is 1 instance where this seems to be happening. PHP Fatal error: 1213:Deadlock found when trying to get lock; try restarting transaction :: UPDATE plugin_control SET infs = 0 ==> (as called by) /var/www/vr156/includes/classes/PluginManager.php on line 199 <== in /var/www/vr156/includes/classes/db/mysql/query_factory.php on line 170.

2nd time i have seen this error, but the initiating script is a non base ZC script. but whenever i see this error, all of my encapsulated plugins revert to a status of "Not Installed".

drbyte commented 3 years ago

@proseLA is the code for this example plugin online? (eg: your "non base ZC script") @zcwilt and I are curious how the "initiating script" is firing inspectAndUpdate, etc etc

proseLA commented 3 years ago

for a minute there, i was able to reproduce it on command. now i can not.

i use adminer for easy access to my db on my development machine. the adminer file is on my dev box; and i created the following script admin2.php in my admin directory:

<?php
define('DO_STRICT_SANITIZATION', false);
require('includes/application_top.php');

function adminer_object() {

  class AdminerSoftware extends Adminer {

    function credentials() {
      return array(DB_SERVER, DB_SERVER_USERNAME, DB_SERVER_PASSWORD);
    }

    function database() {
      // database name, will be escaped by Adminer
      return DB_DATABASE;
    }

    function login($login, $password) {
      return true;
    }
  }

  return new AdminerSoftware;
}

include "./adminer.php";

i now go mydev.com/myadmin/admin2.php to have easy access to my db without the need to enter credentials. here is the full output from log file:

[29-Oct-2020 11:06:23 America/Los_Angeles] Request URI: /myadmin/admin2.php?file=functions.js&version=4.7.7, IP address: 192.168.14.74
#1  trigger_error() called at [/var/www/vr156/includes/classes/db/mysql/query_factory.php:170]
#2  queryFactory->show_error() called at [/var/www/vr156/includes/classes/db/mysql/query_factory.php:142]
#3  queryFactory->set_error() called at [/var/www/vr156/includes/classes/db/mysql/query_factory.php:269]
#4  queryFactory->Execute() called at [/var/www/vr156/includes/classes/PluginManager.php:234]
#5  Zencart\PluginManager\PluginManager->updatePluginControlVersions() called at [/var/www/vr156/includes/classes/PluginManager.php:193]
#6  Zencart\PluginManager\PluginManager->updateDbPlugins() called at [/var/www/vr156/includes/classes/PluginManager.php:23]
#7  Zencart\PluginManager\PluginManager->inspectAndUpdate() called at [/var/www/vr156/myadmin/includes/application_bootstrap.php:161]
#8  require_once(/var/www/vr156/myadmin/includes/application_bootstrap.php) called at [/var/www/vr156/myadmin/includes/application_top.php:15]
#9  require(/var/www/vr156/myadmin/includes/application_top.php) called at [/var/www/vr156/myadmin/admin2.php:3]
--> PHP Fatal error: 1213:Deadlock found when trying to get lock; try restarting transaction :: INSERT INTO plugin_control_versions(unique_key, author, version, zc_versions, infs) VALUES (.....) ON DUPLICATE KEY UPDATE infs = 1 ==> (as called by) /var/www/vr156/includes/classes/PluginManager.php on line 234 <== in /var/www/vr156/includes/classes/db/mysql/query_factory.php on line 170.

now, there are times when the plugins get uninstalled without a log on my dev box.

in addition, i have one client who is live with v157, and makes use of my encapsulated inventory plugin available on the zen-cart site. yesterday that plugin got uninstalled with no log that i could see, and i have no idea how it uninstalled. i'm looking through the ZC admin activity log to see if i can figure out; but alas i can not. there was no adminer activity on his site prior to that happening.

not sure if it helps or not.

drbyte commented 3 years ago

PHP Fatal error: 1213:Deadlock found when trying to get lock

It'd be good to understand why the deadlock is occurring in the first place.

During further discussion with @zcwilt we acknowledge that currently the plugin code, when refreshing its list, resets all to 0 and then updates/enables once verifying things. If the verification loop fails then things are left at 0. Building a detector around the failure to have it re-run the loop might be an option ... but don't want to create an endless loop there either. In theory in this situation simply re-running the detection process should be enough, after the external db problem clears of course.

proseLA commented 3 years ago

It'd be good to understand why the deadlock is occurring in the first place.

i agree. that would be ideal.

During further discussion with @zcwilt we acknowledge that currently the plugin code, when refreshing its list, resets all to 0 and then updates/enables once verifying things. If the verification loop fails then things are left at 0. Building a detector around the failure to have it re-run the loop might be an option ... but don't want to create an endless loop there either. In theory in this situation simply re-running the detection process should be enough, after the external db problem clears of course.

i am not sure why it does this. i can imagine it is to check if there is a new version of a plugin, perhaps?

i suppose it is not that important for me to understand the why. nor is it important to address this situation just for me. i can very easily survive the way it is. i wanted to point it out in case others have similar behavior and we need to address it.

please let me know if i can provide any additional help on it.

njcyx commented 3 years ago

157c (upgraded from 157), php 7.2

I have the same issue. I don't think I have this issue when I upgraded my site from 157 to 157c. Not sure when it is started. It looks like every 24 hours or so, displaylogs plugin is automatically uninstalled (not disabled). I can still manually install this plugin, and it will work for another 24 hours or so. I don't find any logs generated regarding this issue. I don't find any records in admin activity records neither. I just deleted the whole zc_plugins folder, and re-uploaded this folder. Not sure if it helps.

At the same time, I have another clone testing site running under php 7.4. So such issue is found.

njcyx commented 3 years ago

Here is an update. I deleted the whole zc_plugins folder, and re-uploaded this folder. Then upgraded my PHP version from 7.2 to 7.4. It seems worked. Or at least the displaylogs tool is last for more than 24h.

dbltoe commented 3 years ago

157c with 7.2 PHP

I have been having similar problems in that the plugins randomly uninstall. It can be days or a month. No log files and can't correlate with the admin logs.

I will try the jump to 7.4 to see if it makes a difference or adds a log.

PS Using Display Logs, Mod List, and SiteMapXML with the plugin manager.

proseLA commented 3 years ago

this problem remains a problem.

it makes it difficult during development.

and it continues with php v7.4 in my testing.

njcyx commented 3 years ago

I jumped to php7.4 and it worked properly for 3-4 months. Then one day, this issue came back again.

One day, I saw the following post regarding the Plugin Installer. I tried and this bug seems gone (at least good for half month).

https://www.zen-cart.com/showthread.php?228206-Plugin-Installer

proseLA commented 3 years ago

I jumped to php7.4 and it worked properly for 3-4 months. Then one day, this issue came back again.

One day, I saw the following post regarding the Plugin Installer. I tried and this bug seems gone (at least good for half month).

https://www.zen-cart.com/showthread.php?228206-Plugin-Installer

that post has nothing to do with this specific problem.

if you go to my initial post, the problem starts here:

https://github.com/zencart/zencart/blob/f9c31a44a6a6b10e978f2129a2333bf64339f9dd/admin/includes/application_bootstrap.php#L166

if you were to comment that line out, your plugins would remain in an installed status.

if you read @drbyte's post from 10/30/2020, you can see that the inspectAndUpdate method resets everything to un-installed. and then re-installs after some sort of verification. if the verification fails, the plugin would remain in an uninstalled status. why that process is there, i am unclear.

zcwilt commented 3 years ago

So I will be looking at this shortly to see if there is a better way to handle this.

The reason the code works this way is to catch an edge case where someone deletes a plugin, without first uninstalling it and bringing a site down.

I've got a couple of ideas how to make this a bit more bomb proof.

zcwilt commented 3 years ago

So I still don't really see what's wrong with the current code.

It may be that because this code runs on every request, we may hit a race condition, but not convinced. The reports above don't really add anything in terms of tracking the problem.

That said, and as mentioned previously, the main intent of the inspectAndUpdate was to detect if a plugin directory had been deleted in case that caused the plugin manager to run code that no longer existed.

However testing this, seems to show that this isn't a problem as the plugin manager/init system always test for file exists anyway.

so the plan here is to remove the inspectAndUpdate call from every request and to only call on the admin plugin manager page.

EdithAllison commented 3 years ago

A site I'm working on had the same issue, thank you for the fix!

I could not find any reason either. Nothing in error logs, no fatal PHP errors. In case anyone sees something I don't, here's the access log from the time of the error happening (name of URL, IP and admin changed).

The only commen element I can see is a log off, probably due to session expiry from an admin. 

111.111.111.111 - - [17/Aug/2021:13:18:06 +0100] "POST /MyAdmin/index.php?cmd=attributes_controller&action=update_product_attribute&page=2&products_filter=1013 HTTP/1.1" 302 - "https://example.com/MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1893&page=2&products_filter=1013&current_category_id=313" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [17/Aug/2021:13:18:06 +0100] "GET /MyAdmin/index.php?cmd=attributes_controller&page=2&current_category_id=313&products_filter=1013 HTTP/1.1" 200 220324 "https://example.com/MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1893&page=2&products_filter=1013&current_category_id=313" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
222.222.222.222 - - [17/Aug/2021:13:18:17 +0100] "GET /MyAdmin/logoff.php HTTP/1.1" 302 - "https://example.com/MyAdmin/index.php?cmd=orders&oID=15435&origin=index" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36"
222.222.222.222 - - [17/Aug/2021:13:18:17 +0100] "GET /MyAdmin/index.php?cmd=login&camefrom=logoff.php HTTP/1.1" 200 2847 "https://example.com/MyAdmin/index.php?cmd=orders&oID=15435&origin=index" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.159 Safari/537.36"
111.111.111.111 - - [17/Aug/2021:13:18:30 +0100] "GET /MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1877&page=2&products_filter=1013&current_category_id=313 HTTP/1.1" 200 84559 "https://example.com/MyAdmin/index.php?cmd=attributes_controller&page=2&current_category_id=313&products_filter=1013" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [17/Aug/2021:13:18:41 +0100] "POST /MyAdmin/index.php?cmd=attributes_controller&action=update_product_attribute&page=2&products_filter=1013 HTTP/1.1" 302 - "https://example.com/MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1877&page=2&products_filter=1013&current_category_id=313" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [17/Aug/2021:13:18:42 +0100] "GET /MyAdmin/index.php?cmd=attributes_controller&page=2&current_category_id=313&products_filter=1013 HTTP/1.1" 200 220324 "https://example.com/MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1877&page=2&products_filter=1013&current_category_id=313" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [17/Aug/2021:13:18:52 +0100] "GET /MyAdmin/index.php?cmd=attributes_controller&action=update_attribute&attribute_id=1874&page=2&products_filter=1013&current_category_id=313 HTTP/1.1" 200 84559 "https://example.com/MyAdmin/index.php?cmd=attributes_controller&page=2&current_category_id=313&products_filter=1013" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"

same issue the next day. A log off happenend, and I can see keepalive being in use:

111.111.111.111 - - [18/Aug/2021:17:04:22 +0100] "GET /MyAdmin/keepalive.php?_=1629301646014 HTTP/1.1" 200 2 "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"

111.111.111.111  - - [18/Aug/2021:17:07:43 +0100] "GET /MyAdmin/keepalive.php?_=1629301646015 HTTP/1.1" 200 2 "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"

111.111.111.111 - - [18/Aug/2021:17:19:10 +0100] "GET /MyAdmin/logoff.php HTTP/1.1" 302 - "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [18/Aug/2021:17:19:11 +0100] "GET /MyAdmin/keepalive.php?_=1629301646016 HTTP/1.1" 302 - "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [18/Aug/2021:17:19:10 +0100] "GET /MyAdmin/index.php?cmd=login HTTP/1.1" 200 2823 "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
111.111.111.111 - - [18/Aug/2021:17:19:11 +0100] "GET /MyAdmin/index.php?cmd=login&camefrom=keepalive.php&_=1629301646016 HTTP/1.1" 200 2870 "https://example.com/MyAdmin/index.php?cmd=plugin_manager&page=1&colKey=BulkOrders" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:89.0) Gecko/20100101 Firefox/89.0"
torvista commented 2 years ago

I installed the DisplayLogs plugin once the latest fix https://github.com/zencart/zencart/pull/4736 was applied. I see at some point this week, this has uninstalled itself as per this thread.

marco-pm commented 2 years ago

Didn't realize that there was already an issue open for this problem. I too have experienced it several times, and I too have come to the same conclusion (and fix) as yours.

For some unclear reason sometimes the plugins on the file system may not be seen by the inspectAndUpdate() method (called by application_bootstrap when accessing the admin), so it proceeds to delete them from the database. Then (when the admin page is updated etc. so that application_bootstrap is called again) the inspectAndUpdate() method now "sees" them and adds them again (via the updatePluginControl() method) but with status 0 (uninstalled) and empty version field. It happens very rarely but... it happens. I had thought that it could be related to the admin being accessed while I was doing some deployment operations, but it's very, very unlikely and far-fetched. The fact that it happens to a lot of you too makes me think it might be that Deadlock thing found by @proseLA above.

Eventually I moved the inspectAndUpdate() method to the plugin manager page, just like in the commit. For now I have not experienced it anymore, but who knows... Basically it's just a workaround instead of a fix, because now it can still happen when navigating the plugin manager page in the admin.

torvista commented 2 years ago

Happened again and I don't even remember accessing the admin! While this is irritating for simple plugins with no options...its a problem for any that have options that require modification from the default each time.

scottcwilson commented 2 years ago

Reopening based on reports of reoccurrence.

marco-pm commented 2 years ago

To clarify my case: I encountered this issue before the patch, on 1.5.7c. After applying the patch, it hasn't happened so far, but I'm not sure it won't happen again (especially when accessing the plugin page in the admin). Will write here if this is the case.

torvista commented 2 years ago

Overnight these have uninstalled again. I appreciate solving this problem is difficult without being able to replicate it. If someone offers debugging code to generate logs that may help, I'll put that on my production site, but until then I'm disabling inspectAndUpdate. I don't see why it has to run on every pageload on shopfront and admin anyway.

lat9 commented 2 years ago

Could it have anything to do with the keep-alive timer? Just throwing that out there.

torvista commented 2 years ago

Since the keepalive does get registered in the Admin Activity log, additional logging from inspectandupdate could at least prove a link.

marco-pm commented 2 years ago

Overnight these have uninstalled again. I appreciate solving this problem is difficult without being able to replicate it. If someone offers debugging code to generate logs that may help, I'll put that on my production site, but until then I'm disabling inspectAndUpdate. I don't see why it has to run on every pageload on shopfront and admin anyway.

Just to better understand: are you referring to ZC 1.5.7c, or 1.5.7d (so after the patch)? Because in the second case (1.5.7d) the inspectAndUpdate() runs only when you open the plugin manager page. Even on 1.5.7c, the inspectAndUpdate() however is called only in the admin, not in the storefront.

I agree that adding some logging to the inspectAndUpdate() method could help identify the issue.

torvista commented 2 years ago

I am using ZC158 in production, (for my own reasons, and the sky is not falling in). I see inspectandupdate being called from both sides.

marco-pm commented 2 years ago

I am using ZC158 in production, (for my own reasons, and the sky is not falling in). I see inspectandupdate being called from both sides.

Ok, the patch hasn't been included in the 1.5.8 branch (yet?), so the method is still called in application_bootstrap. So I suppose either we apply the same workaround (moving the call to the plugin manager page only) or we try to find the root cause of the problem.

zcwilt commented 2 years ago

So looking at code, v158 is still running inspectAndUpdate on all admin/store calls and hasn't had the updates that v157 had.

zcwilt commented 2 years ago

will look to do a patch tomorrow

zcwilt commented 2 years ago

see https://github.com/zencart/zencart/pull/4752

scottcwilson commented 1 year ago

Can this be closed as fixed by #4752 ?

proseLA commented 1 year ago

i think so. i'm not seeing any activity on it in the wild. i'm comfortable closing, and if it happens again, we can either open a new issue, or re-open it.