New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Upgrade from 8.4 to 8.5 fails #6953

Closed
andrew-thought opened this Issue Nov 2, 2018 · 22 comments

Comments

5 participants
@andrew-thought

andrew-thought commented Nov 2, 2018

Upgraded from 8.4 to 8.5 failed.

did php setup.php --update from CLI completed successfully

now index.php fails exceed 360 sec fcgi script max

just spinning wheel does not load login page

thanks!

@pschuele

This comment has been minimized.

Member

pschuele commented Nov 2, 2018

hi Andrew,

do you have some additional information? maybe you can find the problem in the error logs (webserver, tine20.log, ...).

@pschuele pschuele added the Update label Nov 2, 2018

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 2, 2018

just this in error log
tinelog is empty
[Fri Nov 02 09:23:04.146969 2018] [fcgid:warn] [pid 29812] [client 192.168.50.100:41578] mod_fcgid: read data timeout in 360 seconds
[Fri Nov 02 09:23:04.147041 2018] [core:error] [pid 29812] [client 192.168.50.100:41578] End of script output before headers: index.php
[Fri Nov 02 09:59:02.727134 2018] [fcgid:warn] [pid 10419] (104)Connection reset by peer: [client 192.168.50.100:42630] mod_fcgid: error reading data from FastCGI server
[Fri Nov 02 09:59:02.727218 2018] [core:error] [pid 10419] [client 192.168.50.100:42630] End of script output before headers: index.php

is there a way i can get better log output?
thanks!

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 2, 2018

more info
[Fri Nov 02 14:56:15.509679 2018] [core:error] [pid 16558] [client XX:XX:XX:XX:42930] End of script output before headers: index.php
[Fri Nov 02 14:56:17.602579 2018] [core:error] [pid 18024] [client XX:XX:XX:XX:42964] AH00124: Request exceeded the limit of 10 internal redirects due to probable configuration error. Use 'LimitInternalRecursion' to increase the limit if necessary. Use 'LogLevel debug' to get a backtrace.
[Fri Nov 02 14:56:28.925418 2018] [core:error] [pid 18024] [client XX:XX:XX:XX:42970] AH00124: Request exceeded the limit of 10 internal redirects due to probable configuration error. Use 'LimitInternalRecursion' to increase the limit if necessary. Use 'LogLevel debug' to get a backtrace.
[Fri Nov 02 14:56:39.417268 2018] [core:error] [pid 18015] [client XX:XX:XX:XX:42976] AH00124: Request exceeded the limit of 10 internal redirects due to probable configuration error. Use 'LimitInternalRecursion' to increase the limit if necessary. Use 'LogLevel debug' to get a backtrace.
[Fri Nov 02 14:57:29.257415 2018] [:error] [pid 18433] [client XX:XX:XX:XX:42996] Tine 2.0 can't setup the configured logger! The Server responded: Zend_Log_Exception: "/home/YYYYYY/domains/tine.YYYYYY.com/logs/tinelog" cannot be opened with mode "a" in /home/YYYYYY/domains/tine.YYYYYY.com/public_html/vendor/zendframework/zendframework1/library/Zend/Log/Writer/Stream.php:81\nStack trace:\n#0 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Log.php(146): Zend_Log_Writer_Stream->__construct('/home/mistiqtec...')\n#1 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(781): Tinebase_Log->addWriterByConfig(Object(Tinebase_Config_Struct))\n#2 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(1523): Tinebase_Core::setupLogger()\n#3 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Exception.php(114): Tinebase_Core::getLogger()\n#4 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(956): Tinebase_Exception::log(Object(Zend_Cache_Exception))\n#5 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(1548): Tinebase_Core::setupCache()\n#6 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(1872): Tinebase_Core::getCache()\n#7 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(1945): Tinebase_Core::_searchServerPlugins()\n#8 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(279): Tinebase_Core::_getServerPlugins()\n#9 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(259): Tinebase_Core::getDispatchServer(Object(Tinebase_Http_Request))\n#10 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/index.php(24): Tinebase_Core::dispatchRequest()\n#11 {main}
[Fri Nov 02 15:04:31.091716 2018] [:error] [pid 18432] [client XX:XX:XX:XX:43158] Tine 2.0 can't setup the configured logger! The Server responded: Zend_Log_Exception: "/home/YYYYYY/domains/tine.YYYYYY.com/logs/tinelog" cannot be opened with mode "a" in /home/YYYYYY/domains/tine.YYYYYY.com/public_html/vendor/zendframework/zendframework1/library/Zend/Log/Writer/Stream.php:81\nStack trace:\n#0 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Log.php(146): Zend_Log_Writer_Stream->__construct('/home/mistiqtec...')\n#1 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(781): Tinebase_Log->addWriterByConfig(Object(Tinebase_Config_Struct))\n#2 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/Tinebase/Core.php(1523): Tinebase_Core::setupLogger()\n#3 /home/YYYYYY/domains/tine.YYYYYY.com/public_html/index.php(20): Tinebase_Core::getLogger()\n#4 {main}
[Fri Nov 02 15:06:40.182996 2018] [:error] [pid 18527] [client XX:XX:XX:XX:43210] Tine 2.0 can't

@paulmhh

This comment has been minimized.

Contributor

paulmhh commented Nov 3, 2018

as it says in the log file:
Tine 2.0 can't setup the configured logger!

Zend_Log_Exception: "/home/YYYYYY/domains/tine.YYYYYY.com/logs/tinelog" cannot be opened with mode "a"

check your file/directory permissions etc.

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 3, 2018

Yup did that 777

No dice

I'll try disabling logging

Logging is not the issue

I've been running tine for 10 years with same Config

It's the recursion bug from the upgrade

@paulmhh

This comment has been minimized.

Contributor

paulmhh commented Nov 3, 2018

777 is not a good idea, the log directory should be owned by your webservers user / group and have 775 or something alike

please look at #6949 you have to apply both patches. But that doesn't change the fact that you have a problem with logging and you have to fix it, without logging you will not be able to get any other issue fixed ever. No logging, no fixing.

@pschuele

This comment has been minimized.

Member

pschuele commented Nov 5, 2018

this also looks not ok:

AH00124: Request exceeded the limit of 10 internal redirects due to probable configuration error. Use 'LimitInternalRecursion' to increase the limit if necessary. Use 'LogLevel debug' to get a backtrace.

maybe there is a problem with the rewrite rules?

@pschuele pschuele added the Webserver label Nov 5, 2018

@ignoreigor

This comment has been minimized.

ignoreigor commented Nov 5, 2018

I used to reduce my config, when I had such issues, especially deactivate or change Session- and Caching-Backends after doing an update.
But I must admit that the InternalRecursion-Error sounds strage.

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 5, 2018

i went back to dist config with just database and superuser directives...and i applied the patches #6949
i dont get any errors, just a spinny wheel forever...

here is some more detailed logs not sure if there's anything here

[Mon Nov 05 12:16:07.237130 2018] [authz_core:debug] [pid 1788] mod_authz_core.c(809): [client 192.168.50.100:46072] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:16:07.237184 2018] [authz_core:debug] [pid 1788] mod_authz_core.c(809): [client 192.168.50.100:46072] AH01626: authorization result of : granted
[Mon Nov 05 12:20:12.667919 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:20:12.667976 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of : granted
[Mon Nov 05 12:20:12.668080 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:20:12.668098 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of : granted
[Mon Nov 05 12:20:12.668188 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:20:12.668205 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of : granted
[Mon Nov 05 12:20:12.668273 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:20:12.668289 2018] [authz_core:debug] [pid 1782] mod_authz_core.c(809): [client 192.168.50.100:46152] AH01626: authorization result of : granted
[Mon Nov 05 12:20:12.762188 2018] [deflate:debug] [pid 1782] mod_deflate.c(853): [client 192.168.50.100:46152] AH01384: Zlib: Compressed 2955 to 1146 : URL /index.php
[Mon Nov 05 12:21:04.155508 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:21:04.155559 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of : granted
[Mon Nov 05 12:21:04.155631 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:21:04.155643 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of : granted
[Mon Nov 05 12:21:04.155704 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:21:04.155715 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of : granted
[Mon Nov 05 12:21:04.155748 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of Require all granted: granted
[Mon Nov 05 12:21:04.155758 2018] [authz_core:debug] [pid 1783] mod_authz_core.c(809): [client 192.168.50.100:46170] AH01626: authorization result of : granted
[Mon Nov 05 12:21:04.254628 2018] [deflate:debug] [pid 1783] mod_deflate.c(853): [client 192.168.50.100:46170] AH01384: Zlib: Compressed 2955 to 1146 : URL /index.php

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 5, 2018

ok from browser dev tools i get this

Mixed Content: The page at 'https://tine.XXXXX.com/' was loaded over HTTPS, but requested an insecure script 'http://tine.XXXXX.com/Tinebase/js/fatClient.js-3858daf4605dd064aaa0-FAT.js'. This request has been blocked; the content must be served over HTTPS.
(index):1 Mixed Content: The page at 'https://tine.XXXXX.com/' was loaded over HTTPS, but requested an insecure script 'http://tine.XXXXX.com/index.php?method=Tinebase.getJsTranslations&locale=en&app=all&version=8687f4f0e764fea29d6e03030d9efed8c1dbaf8e'. This request has been blocked; the content must be served over HTTPS.

@pschuele

This comment has been minimized.

Member

pschuele commented Nov 6, 2018

please try it with this config (in config.inc.php, for example):

'tine20URL' => 'https://tine.XXXXXX.com', // set your real tine20 url here

sometimes this is needed for tine20 to work correctly. you might also need this fix (coming with 2018.08.6): ce97cfc

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 6, 2018

thanks i took out the reverse proxy, so going direct http, on fresh install setup.php just hangs

i get this error in browser

Uncaught (in promise) TypeError: Cannot read property '__isLoaded' of undefined
at Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1
at t (Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1)
at Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1
at new Promise ()
at new t (Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1)
at t.default (Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1)
at Object.initLocale (Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1)
at Tinebase-0746e7e3c4ad8cd2003e-FAT.js:1
at b (ext-all.js:7)

@pschuele

This comment has been minimized.

Member

pschuele commented Nov 7, 2018

hm, i have currently no idea what is going wrong. maybe you should wait for the next release 2018.08.6 and try again.

@ignoreigor

This comment has been minimized.

ignoreigor commented Nov 7, 2018

Have you tried my advice to reduce your config.inc.php for the first login after an upgrade? When i changed the code, I had errors because of cached backend-data, result was a spinning spinner. Alternatively I cleaned my redis-cache for tine2.0.

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 7, 2018

thanks ignoreigor!

yes, clean everything, clean apache, config, clean virtual directory, clean config.inc.php from config.inc.php.dist only filled in db and admin info.

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 7, 2018

sorry i also had this in browser

Uncaught SyntaxError: Unexpected token <
from this link address
http://tine.xxxx.xx/index.php?method=Tinebase.getJsTranslations&locale=en&app=all&version=8687f4f0e764fea29d6e03030d9efed8c1dbaf8e

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 7, 2018

got it working 8.5 on clean install

using php command line setup

it bombed exception looking for files directory which i didn't have in the config

Fatal error: Uncaught Tinebase_Exception_Backend: No base path (filesdir) configured or path not writeable in

@msphn

This comment has been minimized.

Member

msphn commented Nov 8, 2018

@andrew-thought You should configure filesdir, some years ago it wasn't required, nowadays it is pretty much integrated everywhere.

I wrote a list of required configuration here: https://michaelspahn.de/tine-20/tine-20-the-installation/
We should probably make those fields mandatory.

@pschuele

This comment has been minimized.

Member

pschuele commented Nov 8, 2018

I'll run a test without the filesdir config. maybe we made it mandatory already by accident ... but the setup gui should work without!

@pschuele pschuele self-assigned this Nov 8, 2018

@pschuele pschuele added this to To do in Tine 2.0 Development via automation Nov 8, 2018

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 9, 2018

thank you guys, i got everything working, still fixing some active sync with proxy issues but i'll get that figured out...

one issue remains and i think i've figured out why the spinny wheel

the only way i can get everything working (with htttps to http reverse proxy) is to allow mixed content, for some reason the scripting is sending the wrong url or the proxy is not mapping it correctly. i saw an old issue from many years ago you guys solved for IE mixed content that was an extjs issue:

this is what i see if i dont allow mixed content:

Mixed Content: The page at 'https://tine.XXXXX.com/' was loaded over HTTPS, but requested an insecure script 'http://tine.XXXXX.com/Tinebase/js/fatClient.js-3858daf4605dd064aaa0-FAT.js'. This request has been blocked; the content must be served over HTTPS.
(index):1 Mixed Content: The page at 'https://tine.XXXXX.com/' was loaded over HTTPS, but requested an insecure script 'http://tine.XXXXX.com/index.php?method=Tinebase.getJsTranslations&locale=en&app=all&version=8687f4f0e764fea29d6e03030d9efed8c1dbaf8e'. This request has been blocked; the content must be served over HTTPS.

in 8.4 i had the same reverse proxy configs but no issues, only thing i can think of is maybe the browsers started enforcing rejecting mixed content?

thanks for all your help!!

@msphn

This comment has been minimized.

Member

msphn commented Nov 9, 2018

I assume Tine 2.0 isn't aware of SSL. I assume you are terminating your SSL at the reverse proxy, the frontend is using SSL but Tine 2.0 assumes the URLs are http:// and constructing them wrong.

Phil stated above that you are able to define the base url of Tine 2.0 within the configuration, did you do so?

@andrew-thought

This comment has been minimized.

andrew-thought commented Nov 9, 2018

yes that fix worked!

and thank you for the config guide Michael, it was very helpful

@msphn msphn closed this Nov 11, 2018

Tine 2.0 Development automation moved this from To do to Done Nov 11, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment