Add note to log when site put into and taken out of Offline mode

Hi
I just crossed the perfect example on why this issue should be taken much seriously: a admin user saw the "outdated message", so thinking doing the right thing he follows the link and follow the update process putting the site in maintenance mode... The update failed but he didn't notice was still in maintenance mode because he was already logged in.
He do it twice over several months...
It take a while to debug it since there is no drupal log, and webserver log didn't show any visit to maintenance page.

Ok, the fault is mainly on the dev team side (update module enable on production site and bad permissions) but still I think this issue shoul get a higher priority (or the first patch should be accepted)

See also: https://github.com/drush-ops/drush/issues/5365

FWIW the last patch still applies cleanly against 9.5.x.

Thanks, I just add it to my `composer.json`.

So the patch number 17 could be marked as RTBTC

The patch still applies cleanly. I don't see any outstanding requests for changes. Switching this to 'needs review.'

The issue summary is pretty bare.

Also could use some kind of test coverage. Even simply coverage.

I am running core version 9.5.11 I tested the patch from #21. I was not able to get anything in logs when setting the maintenance mode through the UI. I tried clearing caches with Drush a few times but it didn't have any effect.

Patch from #17 also applies cleanly and now I got log messages when it was set. But I think the solution in #21 would be better if it worked because we also set maintenance mode with Drush and would be good to catch those also.

As maintenance mode is stored in state, it is good to log message in Drupal\Core\State::set() method. So, moving the fix given in #21 to State.php. This way, there will be a log for both cases - drush and form save. Verified the attached patch with Drupal 10.1.4

@sumit_saini Thanks for the patch - tests are still needed, so moving back to Needs Work.

Aditi Saraf → made their first commit to this issue’s fork.

The last patch is still missing the test(s).

And it would be great to update to update the issue summary (see #42). We should also include the summary of possible solutions (State::set() vs CacheCollector:set() vs SiteMaintenanceModeForm ..), as there are multiple patches with different approaches, so better to have this summarized. Thanks!

Rerolled.

For the issue summary update and tests.

We encountered an error when using this patch in core with Redirect 404 submodule of Redirect.

After upgrading to Drupal 10.2, I get the following error when trying to disable the maintenance mode in en/admin/config/development/maintenance:

The website encountered an unexpected error. Try again later.

TypeError: Drupal\system\Form\SiteMaintenanceModeForm::__construct(): Argument #1 ($logger_factory) must be of type Drupal\Core\Logger\LoggerChannelFactory, Drupal\redirect_404\Render\Redirect404LogSuppressor given, called in /var/www/html/web/core/modules/system/src/Form/SiteMaintenanceModeForm.php on line 74 in Drupal\system\Form\SiteMaintenanceModeForm->__construct() (line 58 of core/modules/system/src/Form/SiteMaintenanceModeForm.php).

Drupal\system\Form\SiteMaintenanceModeForm::create(Object) (Line: 28)
Drupal\Core\DependencyInjection\ClassResolver->getInstanceFromDefinition('\Drupal\system\Form\SiteMaintenanceModeForm') (Line: 48)
Drupal\Core\Controller\HtmlFormController->getFormObject(Object, '\Drupal\system\Form\SiteMaintenanceModeForm') (Line: 58)
Drupal\Core\Controller\FormController->getContentResult(Object, Object)
call_user_func_array(Array, Array) (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 627)
Drupal\Core\Render\Renderer->executeInRenderContext(Object, Object) (Line: 124)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext(Array, Array) (Line: 97)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 181)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 76)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1) (Line: 58)
Drupal\Core\StackMiddleware\Session->handle(Object, 1, 1) (Line: 48)
Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object, 1, 1) (Line: 28)
Drupal\Core\StackMiddleware\ContentLength->handle(Object, 1, 1) (Line: 106)
Drupal\page_cache\StackMiddleware\PageCache->pass(Object, 1, 1) (Line: 85)
Drupal\page_cache\StackMiddleware\PageCache->handle(Object, 1, 1) (Line: 48)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object, 1, 1) (Line: 51)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object, 1, 1) (Line: 36)
Drupal\Core\StackMiddleware\AjaxPageState->handle(Object, 1, 1) (Line: 51)
Drupal\Core\StackMiddleware\StackedHttpKernel->handle(Object, 1, 1) (Line: 704)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)

I’m not convinced by the solution proposed in #21. While it’s nice that the message is logged when the site is put into maintenance mode using Drush, I don’t believe the State class should be responsible for that. Perhaps we could handle it in Drupal\Core\EventSubscriber\MaintenanceModeSubscriber by introducing a second state variable to store the last logged action, which would help prevent log flooding.

In the meantime, I’ve refined the SiteMaintenanceModeForm solution slightly and added a kernel test.

Do you think we should invest effort into covering the Drush case?

Left some small comments on the MR.

Thanks for the review @smustgrave :)

All threads resolved!

I think we should consider an architecture that allows us to log state keys set during a request / cli operation. We could add an property to store the keys that are set during the request to \Drupal\Core\State\State and then add a public method to get this information. Then add a service then subscribes to the terminate even and gets this value and logs any state changes for a list of keys defined in a container parameter. This container parameter should contain the value system.maintenance_mode be default.

This way we'll get consistent logging across Drush / admin UI and any other way of doing this and we'll have a generic system to solve this if we want logging for any other state changes.

We could add an property to store the keys that are set during the request to \Drupal\Core\State\State and then add a public method to get this information. Then add a service then subscribes to the terminate even and gets this value and logs any state changes for a list of keys defined in a container parameter.

In the case of state, and then perhaps generally, would there be a need to track the previous stored value for the key so it can be compared with the new value?

Umm, this is getting interesting. Some thoughts:

1. If system.maintenance_mode is set multiple times within the same request or CLI operation, the last change could be from 1 to 1, which wouldn’t be useful. However, that’s very unlikely to happen, though.
2. If you believe that the final value is what matters most, then storing the previous value isn’t relevant.
3. On the other hand, if you consider the previous value important, I start to worry about an edge case like the one mentioned in point 1.

I think we could just log the current value. However I also think there is a way around #60.1 If we want to also report the initial value then we could easily do something like

if (!isset($this->keySetDuringRequest[$key])) {
  $this->keySetDuringRequest[$key] = $value;
}

And then the method to get the keys set during the request could return the initial value too. I think we should only consider doing that if getting the initial value does not cost anything. I think it is okay to ignore multiple changes to a value during a request and only care about the initial and value value for the purposes of logging.

Sounds good. I'll work into this :)

I think one (small, probably) concern with not getting the initial stored value in the case of maintenance mode is that if the site was already put into maintenance in a prior request or CLI op, then the log will show successive messages indicating maintenance mode was enabled. This might be confusing to someone expecting to see a message about maintenance mode being disabled somewhere in between.

Maybe the log message for maintenance mode can be worded to acknowledge that maintenance mode state was set but not necessarily changed?

I'm not feeling as confident with naming as I usually do while writing this code… maybe it's just late, and I'm not thinking clearly. 🙂

• I'm unsure about the StateKeysSetLoggerSubscriber subscriber name.
• I'm also not completely sure about the service name state.keys_set_logger.
• I feel uneasy about not being able to provide a more specific log message when maintenance mode is set, rather than just logging "The state key system.maintenance_mode has been changed from 0 to 1."

Nonetheless, I believe this approach addresses #60 and the concerns discussed earlier.

Any feedback would be greatly appreciated!

I have no opinion on the class name, but made some comments on the MR.

Also:

I feel uneasy about not being able to provide a more specific log message when maintenance mode is set, rather than just logging "The state key system.maintenance_mode has been changed from 0 to 1."

Detecting what the value has changed from isn't possible without get() call, which I presumed was to be avoided. Though I'm also not sure about the performance impact.

I have another idea, although it's not exactly in linew with @alexpott suggested:

What if we fire a dedicated event for state changes, such as StateKeySetEvent, to which a MaintenanceModeEventSubscriber could listen and log a more specific message?

We could dispatch the event before the key is updated, allowing subscribers to retrieve the original value directly from the state instead of passing it within the event, only in case they need it. This would introduce a performance impact, but only for subscribers that actually need to access the original value. Given that there would only be a few subscribers, the impact wouldn’t be as significant as retrieving the original value for every key set in a request.

What do you think?

@vidorado I'm hesitant to have an event being triggered because this is during termination and only limited things will work as expected - for example you can't use the messenger service and expect something to make it to the page. That said this can be documented so maybe that is okay.

Oh... writing this makes me realise we can completely remove the generic logger and just have a logger for the maintenance mode. And we can change public function getKeysSetDuringRequest(): array; to public function getValueSetDuringRequest(string $key): ?array; and that can return the new and original value in an array or NULL if the key was not changed.

Thanks @alexpott,

I hadn't realized that firing another event during the termination event could be problematic. Thanks for pointing it out.

However, the termination event we were subscribing to was intended to collect all the state keys set during the request, since at that stage, it's very unlikely that any more keys would be set. In contrast, the StateKeySetEvent I suggested would be fired each time a state key is set, rather than at termination.

With this approach, a MaintenanceModeEventSubscriber could listen for system.maintenance_mode being set to 1 and log a message if the original value was 0. This might generate a log entry each time maintenance mode is set during a request, but it's highly unlikely that it would be set more than once.

Would this event subscriber align with the "maintenance mode logger" you suggested? Were you referring to a polling strategy rather than a publisher-subscriber approach?

@vidorado I don't think we should fire an event every time a state key is set. I think the solution suggested in #67 is the way to go. The maintenance mode subscriber can subscribe to the terminate event and do everything it needs. See new MR - https://git.drupalcode.org/project/drupal/-/merge_requests/11220

With the new MR you can see the logging in action with Drush if you are in verbose mode...

vendor/bin/drush -v sset system.maintenance_mode 1
 [info] Drush bootstrap phase: bootstrapDrupalRoot()
 [info] Change working directory to /Volumes/dev/sites/drupal8alt.dev
 [info] Initialized Drupal 11.2-dev root directory at /Volumes/dev/sites/drupal8alt.dev
 [info] Drush bootstrap phase: bootstrapDrupalSite()
 [info] Initialized Drupal site default at sites/default
 [info] Drush bootstrap phase: bootstrapDrupalConfiguration()
 [info] Drush bootstrap phase: bootstrapDrupalDatabase()
 [info] Successfully connected to the Drupal database.
 [info] Drush bootstrap phase: bootstrapDrupalFull()
 [info] Starting bootstrap to none
 [info] Drush bootstrap phase 0
 [info] Try to validate bootstrap phase 0
 [info] Maintenance mode enabled.

vendor/bin/drush -v sset system.maintenance_mode 0
 [info] Drush bootstrap phase: bootstrapDrupalRoot()
 [info] Change working directory to /Volumes/dev/sites/drupal8alt.dev
 [info] Initialized Drupal 11.2-dev root directory at /Volumes/dev/sites/drupal8alt.dev
 [info] Drush bootstrap phase: bootstrapDrupalSite()
 [info] Initialized Drupal site default at sites/default
 [info] Drush bootstrap phase: bootstrapDrupalConfiguration()
 [info] Drush bootstrap phase: bootstrapDrupalDatabase()
 [info] Successfully connected to the Drupal database.
 [info] Drush bootstrap phase: bootstrapDrupalFull()
 [info] Starting bootstrap to none
 [info] Drush bootstrap phase 0
 [info] Try to validate bootstrap phase 0
 [info] Maintenance mode disabled.

That's elegant! 🙂 Thanks for helping out!

Sorry, I wasn’t getting it at first when I read #67, but after view it in code, I got it! :)

I've also learned from it that a complete class constructor parameter promotion can be in the scope of an issue that modifies the class (which I think is cool), and also learned how to do a proper "autowire service promotion".

Overall, I think the code has turned out to be a very lean and clean change.

It works fine, either with Drush or the UI.

Only a question remains:

Should we be concerned about the performance impact of $this->registerKeySetDuringRequest($key, $value, parent::get($key)); being executed for each key set in State? (for the parent::get($key), which will have a cost).

A couple small typos and a question. One test failure as well, presumably unrelated.

godotislate → changed the visibility of the branch 229778-add-note-to to hidden.

godotislate → changed the visibility of the branch 11.x to hidden.

Should we be concerned about the performance impact of $this->registerKeySetDuringRequest($key, $value, parent::get($key)); being executed for each key set in State? (for the parent::get($key), which will have a cost).

I'm not concern because State is a cache collector and it has to get all the values before a set... - see the call to $this->lazyLoadCache(); in both get and set in the parent cache collector class.

One other note is that there is no explicit test with a pre-existing original value. It is tested implicitly in SiteMaintentanceTest, so maybe it's fine?

I added a test case for this.

This looks good now. There is one failing test, but I think it is unrelated and just needs re-running.

I'm not concern because State is a cache collector and it has to get all the values before a set... - see the call to $this->lazyLoadCache(); in both get and set in the parent cache collector class.

I see. State data is cached in-memory in the CacheCollector::$storage variable, so is cheap to retrieve the value with a get() :)

Since all threads and suggestions are resolved, the test are passing (I've launched another pipeline and it passed, the failing tests were the common ones that randomly fail and you must re-run), I believe we can switch to RTBC.

Thanks to all for your work! I've learned a lot from this ^^

We need a change record to detail the addition of StateInterface::getValuesSetDuringRequest() - https://www.drupal.org/node/add/changenotice?field_project=3060&field_is... →

Added CR: https://www.drupal.org/node/3519307 →

I added a couple minor comments on the MR after looking again while writing the CR.

Since the changes look good to me and the tests pass, I believe it's safe to switch back to RTBC.

Thanks @godotislate!

NW per https://git.drupalcode.org/project/drupal/-/merge_requests/11220#note_49.... We should accept that suggestion, then IMHO we should be good to go.

OK, I'll stop messing around. It's already fixed, just we can't resolve threads.

No worries @penyaskito 😁 you're not the only one who has been misleaded by unresolved threads. I don't really know what it depends on. Sometimes I see the "Resolve thread" button at GitLab, but sometimes not.