Avoid db connections when logging db connection errors #37458

nfebe · 2023-03-28T20:37:42Z

\OC\Log\LogDetails::logDetails depends on \OC_App::getAppVersions() which makes a database connection causing the logger to break when the database service is unavaiable.

Resolves: #37424

nfebe · 2023-03-28T20:42:31Z

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)

ChristophWurst · 2023-03-29T07:28:34Z

I do not thing that this fixes #37424 but it's an important and appreciated code cleanup 👍

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.

nfebe · 2023-03-29T07:55:53Z

I do not thing that this fixes #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.

ChristophWurst · 2023-03-29T14:22:33Z

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

Public APIs are tricky :)

lib/public/BackgroundJob/IJob.php

lib/public/BackgroundJob/Job.php

lib/public/Log/ILogFactory.php

lib/private/Log.php

nfebe

Overall, this catches the DB error and displays something like

Fatal error: Uncaught Doctrine\DBAL\Exception: Failed to connect to the database: An exception occurred in the driver: SQLSTATE[08006] [7] could not connect to server: Connection refused Is the server running on host "localhost" (127.0.0.1) and accepting TCP/IP connections on port 5432? in /home/fenn/nextcloud/nextcloud/lib/private/DB/Connection.php:142 Stack trace: #0 /home/fenn/nextcloud/nextcloud/3rdparty/doctrine/dbal/src/Connection.php(1531): OC\DB\Connection->connect() #1 /home/fenn/nextcloud/nextcloud/3rdparty/doctrine/dbal/src/Connection.php(1029): Doctrine\DBAL\Connection->getWrappedConnection() #2 /home/fenn/nextcloud/nextcloud/lib/private/DB/Connection.php(264): Doctrine\DBAL\Connection->executeQuery() #3 /home/fenn/nextcloud/nextcloud/3rdparty/doctrine/dbal/src/Query/QueryBuilder.php(345): OC\DB\Connection->executeQuery() #4 /home/fenn/nextcloud/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php(280): Doctrine\DBAL\Query\QueryBuilder->execute() #5 /home/fenn/nextcloud/nextcloud/lib/private/AppConfig.php(418): OC\DB\QueryBuilder\QueryBuilder->execute() #6 /home/fenn/nextcloud/nextcloud/lib/private/AppConfig.php(226): OC\AppConfig->loadConfigValues() #7 /home/fenn/nextcloud/nextcloud/lib/private/AllConfig.php(217): OC\AppConfig->getValue() #8 /home/fenn/nextcloud/nextcloud/lib/private/Server.php(1840): OC\AllConfig->getAppValue() #9 /home/fenn/nextcloud/nextcloud/index.php(77): OC\Server->getPsrLogger() #10 {main} thrown in /home/fenn/nextcloud/nextcloud/lib/private/DB/Connection.php on line 142

instead of the regular

Internal Server Error

The server encountered an internal error and was unable to complete your request.
Please contact the server administrator if this error reappears multiple times, please include the technical details below in your report.
More details can be found in the server log.

I am also able to see the error in /var/log/apache2/error.log

My expectation was that the customPsrLogger would log to $dataDir.'nextcloud.log' but nothing is written on that log.

Finally I didn't expect to logger to interrupt the sending regular error message that points to the logs.

nfebe · 2023-03-31T00:01:37Z

lib/private/Server.php

@@ -1834,6 +1834,13 @@ public function getLogger() {
 		return $this->get(ILogger::class);
 	}

+	public function getPsrLogger(): LoggerInterface {
+		$logFactory = $this->get(LogFactory::class);
+		$default = $this->getConfig()->getSystemValue('datadirectory', \OC::$SERVERROOT . '/data') . '/nextcloud.log';


getConfig() and getSystemConfig() methods are marked as deprecated, what new method is available to achieve this?

Turns out getSystemValue() and getAppValue() all depend on a working database connection so it causes the issue I reported in my self review.

Is there a way to read the values from config.php that does not require the db set up?

you're probably going to read the config.php directly. At this point, the database is already a goner and it's just about handling the error gracefully, so that is unusual but the only way to do it.

nfebe · 2023-04-14T11:05:07Z

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)

server/lib/private/DB/Connection.php

Lines 138 to 141 in 8a79636

    
           } catch (Exception $e) { 
        
           	// throw a new exception to prevent leaking info from the stacktrace 
        
           	throw new Exception('Failed to connect to the database: ' . $e->getMessage(), $e->getCode()); 
        
           }

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 · 2023-04-14T15:31:38Z

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.

kesselb · 2023-04-25T13:41:54Z

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?

lib/base.php

lib/private/Server.php

index.php

nfebe · 2023-05-03T09:55:24Z

@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

kesselb · 2023-05-03T10:28:32Z

@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 👍

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

come-nc · 2023-05-09T15:23:48Z

index.php

+	\OC::$server->getPsrLogger()->error($ex->getMessage(), [
+		'exception' => $ex,
+	]);


Suggested change

\OC::$server->getPsrLogger()->error($ex->getMessage(), [

'exception' => $ex,

]);

\OC::$server->get(LoggerInterface::class)->error($ex->getMessage(), [

'exception' => $ex,

]);

Or even better

Suggested change

\OC::$server->getPsrLogger()->error($ex->getMessage(), [

'exception' => $ex,

]);

\OCP::Server::get(LoggerInterface::class)->error($ex->getMessage(), [

'exception' => $ex,

]);

index.php

nfebe · 2023-05-09T16:36:22Z

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.

artonge

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

nfebe · 2023-05-09T16:42:00Z

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!

kesselb · 2023-05-09T20:26:53Z

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 👍

server/lib/private/Log/LogDetails.php

Line 54 in fc07627

$request = \OC::$server->getRequest();

server/lib/private/AppFramework/Http/Request.php

Line 123 in fc07627

CsrfTokenManager $csrfTokenManager = null,

CsrfTokenManager -> SessionStorage -> ISession

server/lib/private/Server.php

Lines 1403 to 1405 in b294eda

    
           $this->registerService(\OCP\ISession::class, function (ContainerInterface $c) { 
        
           	return $c->get(\OCP\IUserSession::class)->getSession(); 
        
           }, false);

server/lib/private/Server.php

Line 669 in b294eda

$this->registerAlias(\OCP\IUserSession::class, \OC\User\Session::class);

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

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

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.

lib/private/Server.php

This commit replaces more ILogger method calls with `Psr\Log\LoggerInterface` as we gradually move away from the custom ILogger. This commit aslo, sets the customPsrLogger to not depend on the database to `logfile` config value. Signed-off-by: fenn-cs <fenn25.fn@gmail.com>

`\OC\Log\LogDetails::logDetails` depends on `\OC_App::getAppVersions()` which makes a database connection causing the logger to break when the database service is unavaiable. Signed-off-by: fenn-cs <fenn25.fn@gmail.com>

nfebe · 2023-05-22T17:09:11Z

@ChristophWurst please can you approve this for merging?

ChristophWurst added 2. developing Work in progress technical debt labels Mar 29, 2023

ChristophWurst requested changes Mar 29, 2023

View reviewed changes

lib/public/BackgroundJob/IJob.php Outdated Show resolved Hide resolved

lib/public/BackgroundJob/Job.php Outdated Show resolved Hide resolved

lib/public/Log/ILogFactory.php Outdated Show resolved Hide resolved

nfebe force-pushed the fix/37424/better-501-error-logging branch from 26be809 to a9678df Compare March 30, 2023 11:42

nfebe changed the title ~~WIP: Move away from deprecated ILogger~~ WIP: Improve 501 Error logging (DB connection failures) Mar 30, 2023

nfebe force-pushed the fix/37424/better-501-error-logging branch from a9678df to 32dda6e Compare March 30, 2023 11:47

github-advanced-security bot found potential problems Mar 30, 2023

View reviewed changes

ChristophWurst mentioned this pull request Mar 30, 2023

fix(ocp): Add deprecation version to ILogFactory::getCustomLogger #37480

Merged

4 tasks

nfebe force-pushed the fix/37424/better-501-error-logging branch from 32dda6e to 94953dc Compare March 30, 2023 23:59

nfebe commented Mar 31, 2023

View reviewed changes

szaimen added this to the Nextcloud 27 milestone Apr 13, 2023

nfebe force-pushed the fix/37424/better-501-error-logging branch from 94953dc to f3f988c Compare April 13, 2023 15:15

nfebe changed the title ~~WIP: Improve 501 Error logging (DB connection failures)~~ Avoid database connections when logging about database connection errors Apr 14, 2023

nfebe marked this pull request as ready for review April 14, 2023 15:33

nfebe requested review from miaulalala and ChristophWurst April 14, 2023 15:33

skjnldsv mentioned this pull request May 3, 2023

27.0.0 beta 1 #38038

Merged

artonge reviewed May 3, 2023

View reviewed changes

lib/base.php Outdated Show resolved Hide resolved

lib/private/Server.php Outdated Show resolved Hide resolved

index.php Outdated Show resolved Hide resolved

artonge requested review from icewind1991 and come-nc May 3, 2023 09:20

nfebe force-pushed the fix/37424/better-501-error-logging branch from 130b827 to 7090284 Compare May 4, 2023 16:14

come-nc reviewed May 9, 2023

View reviewed changes

nfebe force-pushed the fix/37424/better-501-error-logging branch from 19b2d0f to 4eac2d8 Compare May 9, 2023 15:28

come-nc reviewed May 9, 2023

View reviewed changes

index.php Outdated Show resolved Hide resolved

skjnldsv added the bug label May 9, 2023

nfebe force-pushed the fix/37424/better-501-error-logging branch 3 times, most recently from b159431 to 6b94a71 Compare May 9, 2023 16:32

nfebe changed the title ~~Avoid database connections when logging about database connection errors~~ Avoid db connections when logging db connection errors May 9, 2023

artonge reviewed May 9, 2023

View reviewed changes

nfebe force-pushed the fix/37424/better-501-error-logging branch from 6b94a71 to e4459fd Compare May 9, 2023 21:02

artonge approved these changes May 10, 2023

View reviewed changes

kesselb reviewed May 10, 2023

View reviewed changes

lib/private/Server.php Outdated Show resolved Hide resolved

come-nc reviewed May 11, 2023

View reviewed changes

lib/private/Server.php Show resolved Hide resolved

come-nc approved these changes May 11, 2023

View reviewed changes

nfebe force-pushed the fix/37424/better-501-error-logging branch from e4459fd to f4c0158 Compare May 11, 2023 11:02

nfebe requested a review from kesselb May 11, 2023 11:03

blizzz mentioned this pull request May 17, 2023

27.0.0 RC1 #38341

Merged

nfebe added 2 commits May 22, 2023 15:17

Avoid db connection when logging db connection errors

d0fc159

`\OC\Log\LogDetails::logDetails` depends on `\OC_App::getAppVersions()` which makes a database connection causing the logger to break when the database service is unavaiable. Signed-off-by: fenn-cs <fenn25.fn@gmail.com>

nfebe force-pushed the fix/37424/better-501-error-logging branch from f4c0158 to d0fc159 Compare May 22, 2023 14:20

blizzz modified the milestones: Nextcloud 27, Nextcloud 28 May 23, 2023

ChristophWurst approved these changes May 24, 2023

View reviewed changes

nfebe merged commit 4220442 into nextcloud:master May 24, 2023

kesselb mentioned this pull request Aug 15, 2023

Outsource CSRF validation #38445

Closed

5 tasks

kesselb mentioned this pull request Oct 4, 2023

fix(OC_Template.php): ensure we throw all errors #40763

Open

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Avoid db connections when logging db connection errors #37458

Avoid db connections when logging db connection errors #37458

nfebe commented Mar 28, 2023 •

edited

Loading

nfebe commented Mar 28, 2023

ChristophWurst commented Mar 29, 2023

nfebe commented Mar 29, 2023 •

edited

Loading

ChristophWurst commented Mar 29, 2023

ChristophWurst left a comment

nfebe left a comment

nfebe Mar 31, 2023

nfebe Mar 31, 2023

miaulalala Apr 13, 2023

nfebe commented Apr 14, 2023

nfebe commented Apr 14, 2023

kesselb commented Apr 25, 2023

nfebe commented May 3, 2023

kesselb commented May 3, 2023

come-nc May 9, 2023

come-nc May 9, 2023

nfebe commented May 9, 2023

artonge left a comment

nfebe commented May 9, 2023

kesselb commented May 9, 2023

nfebe commented May 22, 2023

Avoid db connections when logging db connection errors #37458

Avoid db connections when logging db connection errors #37458

Conversation

nfebe commented Mar 28, 2023 • edited Loading

nfebe commented Mar 28, 2023

ChristophWurst commented Mar 29, 2023

nfebe commented Mar 29, 2023 • edited Loading

ChristophWurst commented Mar 29, 2023

ChristophWurst left a comment

Choose a reason for hiding this comment

nfebe left a comment

Choose a reason for hiding this comment

nfebe Mar 31, 2023

Choose a reason for hiding this comment

nfebe Mar 31, 2023

Choose a reason for hiding this comment

miaulalala Apr 13, 2023

Choose a reason for hiding this comment

nfebe commented Apr 14, 2023

Questions

nfebe commented Apr 14, 2023

Update (now fixed)

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

About the question in the last update

kesselb commented Apr 25, 2023

nfebe commented May 3, 2023

kesselb commented May 3, 2023

come-nc May 9, 2023

Choose a reason for hiding this comment

come-nc May 9, 2023

Choose a reason for hiding this comment

nfebe commented May 9, 2023

artonge left a comment

Choose a reason for hiding this comment

nfebe commented May 9, 2023

kesselb commented May 9, 2023

nfebe commented May 22, 2023

nfebe commented Mar 28, 2023 •

edited

Loading

nfebe commented Mar 29, 2023 •

edited

Loading