server icon indicating copy to clipboard operation
server copied to clipboard
verified publisher icon nextcloud

Avoid database connections when logging about database connection errors

Open nfebe opened this issue 2 years ago • 9 comments

Improve logging when there's a fatal 501 error so that sysadmins can easily see what is wrong.

Resolves: #37424

nfebe avatar Mar 28 '23 20:03 nfebe

As part of this PR, I decided to equally move away from our ILogger since it's deprecated

The ILogger is marked as deprecated with a decision to now use the more stadard Psr\Log\LoggerInterface.

This commit move all logging dependent on our custom ILogger to Psr\Log\LoggerInterface

See : https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md#3-psrlogloggerinterface

The required changes regarding the above is much bigger project that I expected so this is work in progress but it would nice to have feedback it this is the right path.

cc: @ChristophWurst (Thank you in advance)

nfebe avatar Mar 28 '23 20:03 nfebe

I do not thing that this fixes https://github.com/nextcloud/server/issues/37424 but it's an important and appreciated code cleanup :+1:

We have to do this change carefully. There is still a lot of code to rely on ILogger, even if has been deprecated for a while. But we don't want to break apps, yet.

I would suggest to only continue replacing ILogger method calls with LoggerInterface for now, and leave the ILogger constants in place.

ChristophWurst avatar Mar 29 '23 07:03 ChristophWurst

I do not thing that this fixes https://github.com/nextcloud/server/issues/37424 but it's an important and appreciated code cleanup +1

Definitely, it does not. I want to address that in a separate commit and I feel it's more appropriate to do this cleanup first, if it is something that is needed anyways.

We have to do this change carefully. There is still a lot of code to rely on ILogger, even if has been deprecated for a while. But we don't want to break apps, yet.

I noticed that too, and my intention was to do app refactoring-next and append to this commit. In hopes that the tests would potentially flag the biggest issues?

I would suggest to only continue replacing ILogger method calls with LoggerInterface for now, and leave the ILogger constants in place.

Thanks for this early feedback! Happy to implement your current recommendations after hearing you last thoughts given my response.

nfebe avatar Mar 29 '23 07:03 nfebe

I noticed that too, and my intention was to do app refactoring-next and append to this commit.

Note that only a few apps live inside this repos and are tightly bundled with Nextcloud server: https://github.com/nextcloud/server/tree/master/apps. The rest lives in independent repositories.

We will not be able to replace all ILogger usages at once. Let's try to migrate this repo and app repos independently. And once if looks like ILogger isn't use any longer we drop it from the public API found in the \OCP namespace.

ChristophWurst avatar Mar 29 '23 14:03 ChristophWurst

So after setting a Psr compliant logger in index.php it appears to me like the only way to write to the log file is to use one of these methods OC\Log\Errorlog->write() or \OC\Log\File->write() in the catch section of the db connect function where this error is thrown (and caught in index.php without being logged)

https://github.com/nextcloud/server/blob/8a79636bcb407229a677f12f4ececaeaefdcb5b4/lib/private/DB/Connection.php#L138-L141

So something like

		} catch (Exception $e) {
			$logFilePath = \OC::getLogFile();
			$logFile = new File($logFilePath, '', $this->systemConfig);
			$logFile->write('app', 'Log testing', 3); // Throws memory limit exceeded
                        // Additionally
			$connectionErrorLogger = \OC::$server->get(LogFactory::class);
			$connectionErrorLogger = $connectionErrorLogger->getCustomPsrLogger($logFilePath);
			$connectionErrorLogger->error("Test Error Message", []); // Throws memory limit exceeded
			 throw new Exception('Failed to connect to the database: ' . $e->getMessage(), $e->getCode());
		}

Essentially calling various log methods in the OC\DB\Connection->connect() would lead to a memory limit exceeded error.

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 20480 bytes) in /home/fenn/nextcloud/nextcloud/3rdparty/doctrine/dbal/src/Driver/API/PostgreSQL/ExceptionConverter.php on line 81

Questions

  • Is this something that anyone has seen and what could be the issue?
  • Are my conclusions about the methods necessary to write to log file true?

Thank you!

cc : @miaulalala @ChristophWurst

nfebe avatar Apr 14 '23 11:04 nfebe

Update (now fixed)

I added the commit :

Avoid making db connection when logging about database connection

For various reasons, sometimes a database would not be possible. Our file
 logger before this commit has a function call that relies on a db connection
 that is ironic and creates some kind of chicken and egg scenario. This commit,
resolves that.

How does log file look when db there's a db connection problem?

"app":"no app in context","message":{"Exception":"Doctrine\\DBAL\\Exception","Message":"Failed to connect to the database: An exception occurred in the driver: SQLSTATE[08006] [7] could not connect to server: Connection refused\n\tIs the server running on host \"localhost\" (127.0.0.1) and accepting\n\tTCP\/IP connections on port 5432?","Code":7,"Trace":[{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Connection.php","line":1531,"function":"connect","class":"OC\\DB\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Connection.php","line":1029,"function":"getWrappedConnection","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/Connection.php","line":285,"function":"executeQuery","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Query\/QueryBuilder.php","line":345,"function":"executeQuery","class":"OC\\DB\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php","line":280,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":418,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":184,"function":"loadConfigValues","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":374,"function":"getApps","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/legacy\/OC_App.php","line":801,"function":"getValues","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":731,"function":"getAppVersions","class":"OC_App","type":"::"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":193,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":118,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":1111,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":2074,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Files\/View.php","line":119,"function":"getLockingProvider","class":"OC\\Server","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":465,"function":"__construct","class":"OC\\Files\\View","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":1469,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php","line":624,"function":"boot","class":"OC\\Server","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php","line":1181,"function":"init","class":"OC","type":"::"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/index.php","line":35,"args":["\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php"],"function":"require_once"}],"File":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/Connection.php","Line":158,"message":"Failed to connect to the database: An exception occurred in the driver: SQLSTATE[08006] [7] could not connect to server: Connection refused\n\tIs the server running on host \"localhost\" (127.0.0.1) and accepting\n\tTCP\/IP connections on port 5432?","exception":{},"CustomMessage":"Failed to connect to the database: An exception occurred in the driver: SQLSTATE[08006] [7] could not connect to server: Connection refused\n\tIs the server running on host \"localhost\" (127.0.0.1) and accepting\n\tTCP\/IP connections on port 5432?"},"level":1}
{"app":"core","message":{"Exception":"Doctrine\\DBAL\\Exception","Message":"Failed to connect to the database: An exception occurred in the driver: SQLSTATE[08006] [7] could not connect to server: Connection refused\n\tIs the server running on host \"localhost\" (127.0.0.1) and accepting\n\tTCP\/IP connections on port 5432?","Code":7,"Trace":[{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Connection.php","line":1531,"function":"connect","class":"OC\\DB\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Connection.php","line":1029,"function":"getWrappedConnection","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/Connection.php","line":285,"function":"executeQuery","class":"Doctrine\\DBAL\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/doctrine\/dbal\/src\/Query\/QueryBuilder.php","line":345,"function":"executeQuery","class":"OC\\DB\\Connection","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php","line":280,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":418,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":184,"function":"loadConfigValues","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppConfig.php","line":374,"function":"getApps","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/legacy\/OC_App.php","line":801,"function":"getValues","class":"OC\\AppConfig","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":731,"function":"getAppVersions","class":"OC_App","type":"::"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":193,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":118,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":1111,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":2074,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Files\/View.php","line":119,"function":"getLockingProvider","class":"OC\\Server","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":465,"function":"__construct","class":"OC\\Files\\View","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":171,"function":"OC\\{closure}","class":"OC\\Server","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/3rdparty\/pimple\/pimple\/src\/Pimple\/Container.php","line":122,"function":"OC\\AppFramework\\Utility\\{closure}","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":138,"function":"offsetGet","class":"Pimple\\Container","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/ServerContainer.php","line":171,"function":"query","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/AppFramework\/Utility\/SimpleContainer.php","line":65,"function":"query","class":"OC\\ServerContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/Server.php","line":1469,"function":"get","class":"OC\\AppFramework\\Utility\\SimpleContainer","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php","line":624,"function":"boot","class":"OC\\Server","type":"->"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php","line":1181,"function":"init","class":"OC","type":"::"},{"file":"\/home\/fenn\/nextcloud\/nextcloud\/index.php","line":35,"args":["\/home\/fenn\/nextcloud\/nextcloud\/lib\/base.php"],"function":"require_once"}],"File":"\/home\/fenn\/nextcloud\/nextcloud\/lib\/private\/DB\/Connection.php","Line":158,"CustomMessage":"--"},"level":1}

About the question in the last update

I am still not sure why calling various methods (I tried with logger methods such and Log\File->write()) would lead to a memory execeeded exception in DBAL but my best guess is, those methods use a fair amount of memory and are then called multiples times. Printing a string once from the error handling catch for OC\DB\Connection.php leads to the string being printed more than 10 times on output, which implies a db connection is attempted several times for the application is boostraped.

nfebe avatar Apr 14 '23 15:04 nfebe

Our file logger before this commit has a function call that relies on a db connection that is ironic and creates some kind of chicken and egg scenario.

Hi, do you know which function is the issue?

kesselb avatar Apr 25 '23 13:04 kesselb

@kesselb Sorry for the delayed response the function that does this is logDetailsAsJSON.

See : https://github.com/nextcloud/server/blob/master/lib/private/Log/LogDetails.php

nfebe avatar May 03 '23 09:05 nfebe

@kesselb Sorry for the delayed response the function that does this is logDetailsAsJSON.

See : https://github.com/nextcloud/server/blob/master/lib/private/Log/LogDetails.php

Thank you :+1:

It could be \OC_User::getUser() in logDetails then.

kesselb avatar May 03 '23 10:05 kesselb

@kesselb Sorry for the delayed response the function that does this is logDetailsAsJSON. See : https://github.com/nextcloud/server/blob/master/lib/private/Log/LogDetails.php

Thank you +1

It could be \OC_User::getUser() in logDetails then.

https://github.com/nextcloud/server/blob/b294edad804f40618a96116845615831302d0357/lib/private/Server.php#L733

The above line causes the issue. getAppVersions requires a working database connection to fetch the app versions. The function is called in the memcache factory :(

kesselb avatar May 04 '23 18:05 kesselb

The above line causes the issue. getAppVersions requires a working database connection to fetch the app versions. The function is called in the memcache factory :(

Thank you @kesselb .... Are you suggesting that a solution to refactor that method is sort?

For now, the logic is "manually" create the json entry if logAsJSON fails with a database connection error...

		try {
			$entry = $this->logDetailsAsJSON($app, $message, $level);
		} catch (\Doctrine\DBAL\Exception $e) {
		    $entry = json_encode(['app' => $app, 'message' => $message, 'level' => 1]);
}

Please let me what course of action you are suggesting.

nfebe avatar May 08 '23 12:05 nfebe

If the problem really is the call to \OC_App::getAppVersions();, wrapping it in a try/catch should be enough?

come-nc avatar May 09 '23 07:05 come-nc

If the problem really is the call to \OC_App::getAppVersions();, wrapping it in a try/catch should be enough?

This kind of things seem to work for me:

diff --git a/lib/private/Server.php b/lib/private/Server.php
index bb4e217efa3..c0071114b8f 100644
--- a/lib/private/Server.php
+++ b/lib/private/Server.php
@@ -730,7 +730,12 @@ class Server extends ServerContainer implements IServerContainer {
 
                        if ($config->getSystemValueBool('installed', false) && !(defined('PHPUNIT_RUN') && PHPUNIT_RUN)) {
                                if (!$config->getSystemValueBool('log_query')) {
-                                       $v = \OC_App::getAppVersions();
+                                       try {
+                                               $v = \OC_App::getAppVersions();
+                                       } catch (\Throwable $t) {
+                                               // If this throws, we have to ignore it to be able to log errors in database connection
+                                               $v = [];
+                                       }
                                } else {
                                        // If the log_query is enabled, we can not get the app versions
                                        // as that does a query, which will be logged and the logging

Now the problem is that this silently ignore an error. I would feel better if I understood why it’s not possible to log without building OC\Memcache\Factory

come-nc avatar May 09 '23 14:05 come-nc

Now the problem is that this silently ignore an error. I would feel better if I understood why it’s not possible to log without building OC\Memcache\Factory

I added a try-catch that would only catch db connection failures, I guess that's a more convenient work around.

nfebe avatar May 09 '23 16:05 nfebe

So the fix is in Server.php and the other changes in index.php are only to modernize how we get the logger right?

Exactly!

nfebe avatar May 09 '23 16:05 nfebe

Now the problem is that this silently ignore an error. I would feel better if I understood why it’s not possible to log without building OC\Memcache\Factory

Good question :+1:

https://github.com/nextcloud/server/blob/fc076271c791998272856b640be4b63cfe3263a2/lib/private/Log/LogDetails.php#L54

https://github.com/nextcloud/server/blob/fc076271c791998272856b640be4b63cfe3263a2/lib/private/AppFramework/Http/Request.php#L123

CsrfTokenManager -> SessionStorage -> ISession

https://github.com/nextcloud/server/blob/b294edad804f40618a96116845615831302d0357/lib/private/Server.php#L1403-L1405

https://github.com/nextcloud/server/blob/b294edad804f40618a96116845615831302d0357/lib/private/Server.php#L669

\OC\User\Session -> OC\User\Manager -> ICacheFactory

ICacheFactory then uses \OC_App::getAppVersions(); for the cache prefix :cry:

The good news is, that the csrf token manager is not an essential dependency for the request object itself. We can extract the functionality from the request object to an own service.

kesselb avatar May 09 '23 20:05 kesselb

@ChristophWurst please can you approve this for merging?

nfebe avatar May 22 '23 17:05 nfebe