Improve error messages, by including the source

Drupal already has this: there is a backtrace feature for logging which should reveal the cause.

Thanks @cilefen. I searched, but couldn't find much in the official documentations, but found https://www.drupal.org/forum/support/post-installation/2018-07-18/enable... →

So I enabled "Errors and messages" under /admin/config/development/logging) and added $config['system.logging']['error_level'] = 'verbose'; in settings.php and got more info.

As you can see, "Readonly Html Field" is not mentioned nor the field machine name field_ronly. Or do you mean something else, and there is another method, which adds more details, such as the source of the error?

1.1 Warning after creating the node, DEFAULT

Warning: Array to string conversion in Drupal\Core\Entity\Sql\SqlContentEntityStorageSchema::castValue() (line 2579 of core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorageSchema.php).

1.2 Fatal Error after updating node, DEFAULT

The website encountered an unexpected error. Please try again later.

InvalidArgumentException: Cannot set a list with a non-array value. in Drupal\Core\TypedData\Plugin\DataType\ItemList->setValue() (line 62 of core/lib/Drupal/Core/TypedData/Plugin/DataType/ItemList.php).

2.1 Warning after creating the node, WITH error_level verbose

 Warning: Array to string conversion in Drupal\Core\Entity\Sql\SqlContentEntityStorageSchema::castValue() (line 2579 of core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorageSchema.php).

Drupal\Core\Entity\Sql\SqlContentEntityStorageSchema::castValue(Array, Array) (Line: 1375)
Drupal\Core\Entity\Sql\SqlContentEntityStorage->saveToDedicatedTables(Object, , Array) (Line: 969)
Drupal\Core\Entity\Sql\SqlContentEntityStorage->doSaveFieldItems(Object) (Line: 721)
Drupal\Core\Entity\ContentEntityStorageBase->doSave(NULL, Object) (Line: 520)
Drupal\Core\Entity\EntityStorageBase->save(Object) (Line: 804)
Drupal\Core\Entity\Sql\SqlContentEntityStorage->save(Object) (Line: 339)
Drupal\Core\Entity\EntityBase->save() (Line: 270)
Drupal\node\NodeForm->save(Array, Object)
call_user_func_array(Array, Array) (Line: 114)
Drupal\Core\Form\FormSubmitter->executeSubmitHandlers(Array, Object) (Line: 52)
Drupal\Core\Form\FormSubmitter->doSubmitForm(Array, Object) (Line: 595)
Drupal\Core\Form\FormBuilder->processForm('node_art2_form', Array, Object) (Line: 323)
Drupal\Core\Form\FormBuilder->buildForm(Object, Object) (Line: 73)
Drupal\Core\Controller\FormController->getContentResult(Object, Object)
call_user_func_array(Array, Array) (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 580)
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: 169)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 81)
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: 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: 23)
Stack\StackedHttpKernel->handle(Object, 1, 1) (Line: 718)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)

2.2 Fatal Error after updating node, WITH error_level verbose

The website encountered an unexpected error. Please try again later.

InvalidArgumentException: Cannot set a list with a non-array value. in Drupal\Core\TypedData\Plugin\DataType\ItemList->setValue() (line 62 of core/lib/Drupal/Core/TypedData/Plugin/DataType/ItemList.php).

Drupal\Core\TypedData\TypedDataManager->getPropertyInstance(Object, 'value', 'Array') (Line: 120)
Drupal\Core\TypedData\Plugin\DataType\Map->get('value') (Line: 164)
Drupal\Core\TypedData\Plugin\DataType\Map->getProperties() (Line: 186)
Drupal\Core\TypedData\Plugin\DataType\Map->getIterator() (Line: 162)
Drupal\Core\TypedData\Validation\RecursiveContextualValidator->validateNode(Object) (Line: 163)
Drupal\Core\TypedData\Validation\RecursiveContextualValidator->validateNode(Object) (Line: 163)
Drupal\Core\TypedData\Validation\RecursiveContextualValidator->validateNode(Object, Array, 1) (Line: 105)
Drupal\Core\TypedData\Validation\RecursiveContextualValidator->validate(Object, NULL, NULL) (Line: 93)
Drupal\Core\TypedData\Validation\RecursiveValidator->validate(Object) (Line: 132)
Drupal\Core\TypedData\TypedData->validate() (Line: 489)
Drupal\Core\Entity\ContentEntityBase->validate() (Line: 188)
Drupal\Core\Entity\ContentEntityForm->validateForm(Array, Object)
call_user_func_array(Array, Array) (Line: 82)
Drupal\Core\Form\FormValidator->executeValidateHandlers(Array, Object) (Line: 275)
Drupal\Core\Form\FormValidator->doValidateForm(Array, Object, 'node_art2_edit_form') (Line: 118)
Drupal\Core\Form\FormValidator->validateForm('node_art2_edit_form', Array, Object) (Line: 591)
Drupal\Core\Form\FormBuilder->processForm('node_art2_edit_form', Array, Object) (Line: 323)
Drupal\Core\Form\FormBuilder->buildForm(Object, Object) (Line: 73)
Drupal\Core\Controller\FormController->getContentResult(Object, Object)
call_user_func_array(Array, Array) (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 580)
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: 169)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 81)
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: 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: 23)
Stack\StackedHttpKernel->handle(Object, 1, 1) (Line: 718)
Drupal\Core\DrupalKernel->handle(Object) (Line: 19)

Just saw this, great improvement!

@cilefen: Am I using the correct method? Or is there another method, which will point me to the real source of the problem, i.e. the contrib module "Readonly Html Field"?

PS. I have created the documentation page Enable verbose error logging for better backtracing and debugging → , and hope someone can review it, and add it to the menu links under "Development tools".

Evidently node_art2_edit_form is the problem.

Yes. But we already know that, since that is the form for that content type, and the error appears if you try to edit and save that content type.

What would be great, is if the error message could be more precise, and pin point that the source of the error message is that the contrib module "Readonly Html Field" allows an empty value (as I understand it) ... perhaps @wombatbuddy or @Steven Snedker can add additional info?

See https://www.drupal.org/project/readonly_html_field/issues/3350712#commen... 🐛 Fails on Drupal 9.5+ Fixed

What would be great, is if the error message could be more precise, and pin point that the source of the error message is that the contrib module "Readonly Html Field" allows an empty value (as I understand it)

I don't think this is possible. Systems aren't that intelligent. When a module puts out some bad code, it is used, until it causes an error. The error doesn't happen when the module passes the bad code. What you see is where the error actually turns fatal, and it tells you exactly how it got there with the backtrace. I don't see how there is anyway for the system to be able to know it's because some module passed null instead of a string, especially if the passing of that value happens in a caching phase, and your error happens when that cache is retrieved.

Thanks for clarifying @jaypan, that was what I feared ...

Ideally, it should be possible to "step back" to the event right before the error happened, in order to find the actual culprit. But like you say (if I understand it correctly) if the value has been ferried around in the system for several steps, the source might be quite a few steps removed ... I found the issue PhpStorm take a step back in debugger, which discusses this as well, mentioning the Dontbug reverse debugger, which looks interesting.

Ideally, it should be possible to "step back" to the event right before the error happened, in order to find the actual culprit.

That's exactly what the backtrace is.

But like you say (if I understand it correctly) if the value has been ferried around in the system for several steps, the source might be quite a few steps removed ...

Essentially something like that.

For example, a module calls a system function that requires a string, but gets null. Not enough for a fatal error, so that system function returns a value. Then the modules caches that value for use later. Drupal is fired up for a request, the cached value is retrieved and causes a fatal error. There is no way for Drupal to know at runtime this was because the original module made a mistake and cached a bad value. But it can tell you the exact stack of calls that led to the error, which then requires debugging to determine how it got to that point.

Thanks for clarifying the process @jaypan, it makes more sense to me now.

Ideally, it should be possible to "step back" to the event right before the error happened, in order to find the actual culprit.

That's exactly what the backtrace is.

Heh, I guess I should try to be as precise as possible: What I mean is, step back (or backtrace) to where the source of the error originated. In this case, the faulty value supplied by the contrib module "Readonly Html Field".

In this example, it would have been enormously helpful if the name of the offending field was mentioned, which would have given a hint on where to look. In my content type during testing, the content type name is Art2 and the "Readonly Html field"-field is called Ronly:

Name - machine_name

Content type: Art2 - art2
Field: Ronly - field_ronly

So would it be possible to somehow include field_ronly in the backtrace, something like this?

Drupal\Core\Form\FormBuilder->processForm('node_art2_edit_form', Array, Object) (Line: 323) <<< EXISTING
Drupal\Core\Form\FormBuilder->processForm('field_ronly', Array, Object) (Line: 323)       <<< POSSIBLY INCLUDE FIELD?

Do we need a new fifth level "All messages, with detailed backtrace information" (super_verbose) for this?
Enable verbose error logging for better backtracing and debugging →

So would it be possible to somehow include field_ronly in the backtrace, something like this?

Backtraces are not generated, and do not have things included. The backgtrace shows the function calls, right from the initial request, that shows how the error came about, from the start of the request in index.php right down to the exact function where the error occurs, so that you can trace back to find exactly what happened. The system can't know what happened - that's why the error is fatal, as the system has no idea how to handle the issue, because it doesn't know what happened. It would need to know what happened, to be able to say 'it was because of this module'.

Consider this theoretical flow:

1. Book module creates a page
2. Drupal executes hook_node_insert(). The hook is called in all modules that implement it.
3. Bad module does something, and creates bad code, but not fatal, and returns it to Drupal.
4. Good module does other stuff, and returns it to Drupal.
5. Hook_node_insert() is now complete, so the function calls from step 2, 3 and 4 are not part of the backtrace anymore.
6. The book page created is now to be rendered. The Drupal system renders the new node (book page) into HTML.
7. The data generated in step 3 was bad, and is part of the Node object. Drupal tries to render it, and PHP 'whoops, something is really, really wrong here, I don't know what to do' and you get a fatal error. Here are the list of functions that led to this step.

The backtrace shows the hierarchy to drill down to the function where the fatal error occurred. It requires debugging to actually determine why that failed, and the backtrace will show you exactly where to look. But the system can't know why the error happened, if it knew, it wouldn't be an error. So it requires a human to go look through the code, and track the data to determine why the data that exists isn't something the system can handle.

It would be awesome if there were a way to say 'it's Bad Module's fault'!. But if there were, it would likely already exist, as fatal errors are a nightmare for every developer, and there are thousands of tools around improving development of Drupal, but none that I've ever seen that could really provide this functionality.

Personally, I use a debugger (XDebug) for solving issues like this. You can throw a breakpoint right where the error occurs, to examine all the available data at that point, and identify what the offending code is. Once you do that, you can then work backwards through the backtrace to determine where the offending data came from, whether it was a cache or whatnot. Often, you can see a module name in the backtrace, which is particularly helpful when it's a module/them you've developed, as offending code is usually your own :) When data is pulled from a cache, you can then work to determine how that cache is originally generated, to try to find the code that cached something bad.

The frustration is real, I just don't see how the solution you are looking for could be developed. Of course, I'm just one man, and I would love it if someone proved me wrong, as it would make my life easier! But I wanted to explain why the backtrace, while often not seeming to provide the information you want, is probably the best you're going to get, and is the route to determining what went wrong.

Thanks so much for elaborating about the information included in the backtrace error report @jaypan, and how it works, I really appreciate it.

As you write, it's not currently possible to step up the chain of events and backwards, to the actual source of the error.

But in the case of this specific bug, isn't it possible to at least point out that an empty field was the missing bit, and which field it was? Just getting the field's machine name field_ronly included in the error report would have helped a lot. The form machine name node_art2_edit_form is included, after all.

About, Xdebug: As you write, it is probably the best tool currently, to get knee deep in the code, by adding breakpoints and dissecting the variables, and look for anomalies. I would love to get it working and have previously tried and failed many years ago. I use Sublime Text 4 editor, and have created Xdebug and Sublime Text 4 support request #3543, to hopefully get Xdebug and Sublime Text 4 support in Lando at some point. It would be fantastic.

Still, and I know I am aiming for the stars here, but it would super awesome with a step up/back in the chain of events debugging feature, to the cause of the error and am updating the Issue Summary, with use cases in descending order of perfection, under "Wish list for better Drupal error debugging". Thanks again, and have a nice day.

I've set up xdebug to work with VS Code following these instructions → (here's a video). I hope Sublime Text works more or less the same way.

Xdebug It shaves a few minutes off debugging as you do not have to print or log as many values. But it's not a silver bullet.

I'm afraid Jaypan's fine explanation is correct in most cases.

In this particular case:

Warning: Array to string conversion in Drupal\Core\Entity\Sql\SqlContentEntityStorageSchema::castValue() (line 2579 of core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorageSchema.php).

Drupal Core could probably try to var_dump Array in order to help the blameless Drupal webmasters. That might sometimes give someone a clue as to where the bug might be located. But sometimes the arrays are so huge, that trying to var_dump them will just give you a memory error on the server and/or kill your browser.

In this particular case var_dumping the array held no clue whatsoever as to where the bug was located.

And the verbose backtrace consisted of:

• 32 Drupal\Core\
• 3 Symfony\Component\HttpKernel
• 2 Drupal\page_cache\
• 1 Stack\StackedHttpKernel

All of them clearly correct, but not particularly helpful. Red herrings.

The core architecture of Drupal 8+ will have to change significantly for errors like these to be solveable in a reasonable amount of time by a reasonably experienced developer or webmaster.

The core architecture of Drupal 8+ will have to change significantly for errors like these to be solveable in a reasonable amount of time by a reasonably experienced developer or webmaster.

I don't see a way that it could be changed to report where the error came from, for the reasons I posted earlier. How do you see changing core to be able to see where the error came from? The sentiment of your comment seems nice, but it also seems fanciful, without the actual real-world possibility of doing this.

The bug hunts in Drupal 4-7 were shorter. The simpler architecture meant that you could usually locate the bug in minutes instead of hours. You only had to spend minutes on trial&error, not hours.

Sadly neither I can see a path ahead toward better error reporting in (soon to be obsolete) Drupal 8 and 9.

We might collectively make Drupal 10 a little bit more robust by making our code more robust, using way more is_string(), !empty(), isset(), get_class() etc. But the error reporting will be stuck at suck, I'm afraid. It's way above my technical and social skills to affect useful change here.

This bug/sad state of affairs reminds of an old Drupal 7 bug:

format_date blows up with an unintelligible error message if it gets NULL or thinks the numbers it gets are strings.

Fixing this now been discussed for 10 years (!).

Bright and friendly people have made format_date more robust with a few lines of additional code → .

Result?
They have been asked to:
A) to follow Drupal's syntax to the letter
B) not to actually make the format_date function more robust. Or spew a useful error, when fed, say, a NULL value.

After 10 years of discussion and great fixes, it's a "Won't fix!"

Oh well. Still I will try to be a charitable developer and at least try to make my own modules as robust as possible and provide useful error messages. I wouldn't like for Drupal to turn inscruteable and unforgiving everywhere.

@Steven Snedker: I spent a lot of time trying to get Xdebug running with Sublime Text and sadly failed.

It looked like VS Code or PhpStorm were the two viable candidates, and since I don't want to use Microsoft products such as VS Code I was left with PhpStorm.

Luckily, I discovered that Drupal contributors with +35 issue credits the past year can get a free PhpStorm license → . After getting Xdebug running fairly easily, I added PhpStorm and Xdebug in Lando → .

I recently started using DDEV and added Xdebug instructions for DDEV → as well just now. It was even easier to set up, as can be seen by the few steps it takes. It is basically Plug and play, very impressive.

I agree that Xdebug makes dumping variables much easier, but that it is no silver bullet. Since we have concluded that it is not currently possible, the actionable issue and big challenge then is to make it so, either via Drupal, Symfony, or something else. Only time will tell, if this becomes possible at some point.