Suitecrm: Interrupted / Hanging Upgrades

[pgorod]

Issue

Several manifestations of Upgrade problems. The most frequent are the upgrade hanging at a certain step, or at the very end (in which case the upgrade actually succeeds in taking you to the next version). Sometimes there is a HTTP 500 error sent to the client.

Sometimes there is a php zend_mm_heap corrupted in the Apache log.

The problem occurs due to long delays in cleaning up the temp directory, which crash PHP in a way that doesn't leave any traces in the logs most of the times... the problem tends to aggravate significantly after occurring more than once, since the files accumulate in this directory.

Quick Workaround

If you just want to get your upgrade done, often all that is needed is to clear the entire contents of cache/upgrades/temp and start again.

Actual Behavior

The function unlinkUWTempFiles calls a function findAllFiles which is _very_ inefficient for large directories. It recursively goes through every file in the directory tree, adding each element to an array, then sorting it, then sorting it again, and then deleting each file individually.

So it's a long period of disk read activity, starving the process memory, followed by a long period of CPU intensive operations, followed by a long period of disk write activity.

Possible Fix

This sort of directory iteration should be done using a PHP language construct called Iterator. Instead of making a huge array of files first, and then looping through each item to perform some function, it should just get the necessary item at the moment it needs to act on it. No significant memory consumption, and much simpler code. I will provide a PR.

Steps to Reproduce

1. Run an upgrade to one of the newest versions, like 7.10.9 or 7.10.10.
2. Keep an eye on cache/upgrads/temp to see how many copies of the unzipped package you have there. They add up after each time the process hangs.
3. If necessary to help reproduce, make these copies yourself. Fill that directory with tens of thousands of files. Each package has around 22k. I had a real-life situation with over 90k files.
4. After the upgrades conclude, this directory should be completely empty. If not, then this issue occurred.

Additional tools that might help (Linux, needs sudo)

• htop - a fancier top. Shows CPU usage and other details. when you see an Apache process that is taking up 100% of the CPU, note its PID.
• iotop see aggregated disk activity, by process. Similar to top or htop, but for disk access.
• lsof -n -p 1234 | grep -v mem - get a momentary glimpse of what a process with PID 1234 is doing in terms of file accesses, file by file. You can repeat this command and see that it's iterating the directory, and check if it's reading or writing.
• watch - repeats a command every n seconds. Useful to leave separate terminals showing you regular updates of the above tools' output. I used these

Observe file accesses of process with PID 1234:
watch -n 2 'lsof -n -p 1234 | grep -v mem'

Track directory size dynamically:
watch -n 2 'du -h --max-depth=1 cache/upgrades/temp'

Environment

• SuiteCRM Version used: problems started around version 7.10.7 up to 7.10.10

[pgorod]

@gunnicom you mentioned in Gitter you're working on upgrades, make sure you check out this issue and the PR. Thanks.

[connorshea]

👍 I think I saw this before when upgrading to 7.10.17 on one of our sites

[bdcomp]

@pgorod It looks very similar to an issue #7242, been reported by me about 6 months ago!..
After several times I tried to bring some attention to it, I gave up...

[pgorod]

@bdcomp yes, I agree it must be the same. And I am convinced there are other issues out there for the same basic problem.

All these earlier reports were useful - we knew there was a problem and we are looking for it. But until very recently we couldn't reproduce it consistently. Once I got my hands on a test system that was failing every time, I was able to diagnose and understand what was going on. Thanks for reporting, and for insisting! :wink:

[gunnicom]

For me removing cache/upgrades did not help. Still get the error:
[Tue Nov 12 14:39:10.812342 2019] [proxy_fcgi:error] [pid 80514:tid 140637234849536] [client IPADRESS:57872] AH01071: Got error 'PHP message: PHP Notice: Undefined index: sqlSkippedQueries in /var/www/SUITE/modules/UpgradeWizard/commit.php on line 85PHP message: PHP Notice: Undefined variable: suitecrm_version in /var/www/SUITE/cache/upgrades/temp/L6VL5X/scripts/pre_install.php on line 88PHP message: PHP Notice: Undefined index: post_install in /var/www/SUITE/modules/UpgradeWizard/uw_utils.php on line 3113PHP message: PHP Notice: Undefined variable: path in /var/www/SUITE/cache/upgrades/temp/L6VL5X/scripts/post_install.php on line 210PHP message: PHP Notice: Undefined variable: path in /var/www/SUITE/cache/upgrades/temp/L6VL5X/scripts/post_install.php on line 215PHP message: PHP Warning: "continue" targeting switch is equivalent to "break". Did you mean to use "continue 2"? in /var/www/SUITE/jssource/Minifier.php on line 240PHP message: PHP Warning: dir(/var/www/SUITE/cache/upgrades/temp/L6VL5X/scripts/files_to_add_post/themes/): failed to open dir: No such file or directory in /var/www/SUITE/include/dir_inc.php on line 57PHP message: PHP Fatal error: Uncaught TypeError: Argument 1 passed to SugarController::showException() must be an instance of Exception, instance of Error given, called in /var/www/SUITE/include/MVC/Controller/SugarController.php on line 390 and defined in /var/www/SUITE/include/MVC/Controller/SugarController.php:384\nStack trace:\n#0 /var/www/SUITE/include/MVC/Controller/SugarController.php(390): SugarController->showException(Object(Error))\n#1 /var/www/SUITE/include/MVC/Controller/SugarController.php(401): SugarController->showException(Object(SuiteCRM\StateSaverException))\n#2 /var/www/SUITE/include/MVC/Controller/SugarController.php(380): SugarController->handleException(Object(SuiteCRM\StateSaverException))\n#3 /var/www/SUITE/include/MVC/SugarApplication.php(113): SugarController->execute()\n#4 /var/www/SUITE/index.php(52): SugarApplication->execute()\n#5 {main}\n thrown in /var/...', referer: https://SUITE/

[pgorod]

@gunnicom that seems like a different error, in fact. I think the problem is with this part

PHP Warning: dir(/var/www/SUITE/cache/upgrades/temp/L6VL5X/scripts/files_to_add_post/themes/): failed to open dir: No such file or directory in /var/www/SUITE/include/dir_inc.php on line 57

the rest is just the consequence.

@Dillon-Brown do you have any idea why this could be happening?

[Dillon-Brown]

@pgorod Agreed that the problem is almost certainly with the files_to_add_post/themes/ stuff. I have seen this raised once before on the forums but not sure on the cause and I haven't been able to replicate.

I'm guessing there might be some logic in modules/UpgradeWizard/uw_utils.php that runs if it detects custom themes and then looks to copy over any theme files in files_to_add_post (Of which there aren't any), seems strange though.