Improve doing_it_wrong() and stop it from breaking WP

[azaozz]

The output of _doing_it_wrong() when WP_DEBUG_DISPLAY is true is somehow not that useful. Perhaps we can do a backtrace there. This would also help beginner PHP programmers a lot.

Edit: storing the warnings in a global when WP_DEBUG_DISPLAY is true and outputting them at the top of the screen is a worthy enhancement too.

[azaozz]

This is on the borderline for "plugin material" :) however being a plugin would mean the people that need it most won't probably have it.

[nacin]

I would rather point them toward Log Deprecated Notices or Debug Bar, which handles these kinds of backtraces very effectively.

In my experience coding Log Deprecated Notices, different uses in core require different steps up the tree. It's painful, and exacting, and I believe it belongs in a plugin if only because it can be iterated quickly:

​http://plugins.trac.wordpress.org/browser/log-deprecated-notices/trunk/log-deprecated-notices.php?rev=392669#L252

The best thing we can do for beginner programmers is point them toward established development tools.

[scribu]

Agree with nacin. Maybe add a link to some codex page that would then point to the Debug Bar and Log Deprecated Notices plugins.

[scribu]

Marked #18512 as dup.

[nacin]

Reading #18512 and the patch from Chris, I think I still agree this is plugin material for now. How expensive is a backtrace? I don't think I'd like this running on every pageload, even with WP_DEBUG.

I'm tempted to include a link to the Debug Bar plugin in wp-config-sample.php where we reference WP_DEBUG, and maybe even in every trigger_error() in the _deprecated_* and _doing_it_wrong() functions. Or a link to codex.wordpress.org/Debugging_in_WordPress which can pimp things like WP_DEBUG, the Debug Bar, and Log Deprecated Notices.

Other than performance, the other issue is that the backtrace is going to lie, pretty often, depending on how it is used in the plugin and how the notice is triggered in core.As pointed about above, the code from LDN is pretty painful.

I'd be happy to revisit this but I'm just not convinced yet.

[mikeschinkel]

Replying to nacin:

Reading #18512 and the patch from Chris, I think I still agree this is plugin material for now. How expensive is a backtrace? I don't think I'd like this running on every pageload, even with WP_DEBUG..

Maybe I'm missing something, but doesn't this only run on a warning/error and not on every page load? If yes, the being expensive isn't an issue, right?

[nacin]

Replying to mikeschinkel:

Maybe I'm missing something, but doesn't this only run on a warning/error and not on every page load? If yes, the being expensive isn't an issue, right?

Every page load that has the warning/error -- which, in the case of conditional tags or enqueued scripts (the main two instances of _doing_it_wrong) would be pretty much every pageload. Once nice thing about our deprecated logging is that they don't have any expensive aspects to them, which means WP_DEBUG could be safely run in production.

I use Xdebug and I get my backtraces just fine ;-)

[mikeschinkel]

Replying to nacin:

Every page load that has the warning/error -- which, in the case of conditional tags or enqueued scripts (the main two instances of _doing_it_wrong) would be pretty much every pageload.

You write code where there are warnings or errors on every page load? Seriously?

P.S. I think we need to give you a new nickname: "Dr. No." ;-)

[azaozz]

Replying to nacin:

I'm tempted to include a link to the Debug Bar... Or a link to codex.wordpress.org/Debugging_in_WordPress which can pimp things like WP_DEBUG, the Debug Bar, and Log Deprecated Notices.

Yeah, perhaps this is the better option. Even if backtrace is not very expensive it's just another function to run. Including links to the plugins in all deprecated and _doing_it_wrong warnings would potentially be more beneficial too.

[scribu]

Including links to the plugins in all deprecated and _doing_it_wrong warnings would potentially be more beneficial too.

I hope we are thinking of doing that automatically from _doing_it_wrong() and _deprecated_*(), as opposed to duplicating it on each call to them.

[azaozz]

Replying to scribu:

Of course, the links would be the same in all cases. No need to repeat them.

[chrisbliss18]

Here's some food for thought regarding performance and memory consumption impact due to backtrace parsing as found in my supplied patch.

I set up a site that had large objects running inside of nested actions and function calls, resulting in large backtrace outuput. I then kept track of the difference in memory consumption and execution time. The backtrace code is slightly modified from my supplied patch as it now can show either the source file and line number or class and function name (depending on the content of the specific backtrace entry). I'll update my patch to reflect this conditional shortly.

I ran three tests: Shallow, a single backtrace from the top of a theme's functions.php file (serialized backtrace size: 967 bytes). Single (Deep), a single backtrace from deep inside a large object with a very deep call stack (serialized backtrace size: 78,792 bytes). Multiple (Deep), a dozen backtraces deep inside call stacks of large objects (serialized backtrace size: 158,015 - 162,008 bytes). With these tests, I hoped to derive some expectations of the cost of such backtrace detail generation.

Type	Samples	Serialized Backtrace Size	Time Difference	Memory Difference
Control	103	0	0	0
Shallow	104	967 bytes	+0.0010389 seconds	+20,736 bytes
Single (Deep)	104	78,793 bytes	+0.0004531 seconds	+388,303 bytes
Multiple (Deep)	103	158,015 bytes	+0.0186892 seconds	+913,524 bytes

Note that I used "memory_get_peak_usage()" to generate memory usage and "microtime( true )" to generate the timings. To keep the testing consistent in how it taxed the system, I used ab (Apache Bench) to run 100 tests (for a good sample size) with a concurrency of 1 (to make sure that the concurrency didn't open up some kind of PHP caching technique which showed when I upped the concurrency).

All in all, I think the test went well. The two deep samples aren't exactly cheap but they aren't too expensive either as I've seen very simple plugins make a bigger performance and memory impact than any of these test cases. Of course, since it is possible for there to be backtraces in worse scenarios than my samples, I suppose the value is purely academic.

I still would like to see if it is possible to incorporate simple backtrace output into the notice as this keeps the information inline with the kind offered by PHP's own notices. However, providing information on how to gain access to this information is still a positive step forward as I just don't like the idea of leaving novice developers in the dark on how to find the source of the notice. In other words, I don't want WordPress to have any dastardly "Null Pointer Exception" messages as found in Java where, if you see the message, you might as well just do something else as you aren't likely to find the source of the issue for a while in a large project. I would clarify what I mean more, but I'm sure that you'll figure it out. ;)

[chrisbliss18]

Add simple backtrace output of just the file and line number of the offending code

[azaozz]

18453-2.patch drops the backtrace parsing and implements links to two plugins that can be used to get more info.

It also stops showing of the errors directly when WP_DEBUG_DISPLAY is true so we don't make WP unusable, "headers already sent...", etc. and implements a global that holds the error messages for displaying later at the top of the screen.

[azaozz]

The whole doing_it_wrong concept is actually NUX for new developers and beginner PHP programmers that are starting to work with WordPress. Currently the errors it spits are very unfriendly and often break the rest of the output (headers already sent, etc.).

IMHO we can afford to make the experience a little better. We won't need to do a lot of hand-holding but can at least tell these users that they need a debugging plugin in a nicer way without breaking WP :) The same is true for all the deprecated notices.

In that terms I think something like 18453-2.patch is a needed enhancement and it should include all deprecated notices too. The only thing it still needs is to remove the direct links to plugins and instead link to a codex page about debugging in WordPress.

[azaozz]

Didn't realize that at first but storing the warnings in a global when WP_DEBUG_DISPLAY is true and outputting them at the top of the screen prevents breaking of all XHR requests and wp_cron. It also will prevent these warning from showing in search engines if WP_DEBUG is run on a live site.

Thinking we should handle all deprecated and doing_it_wrong warning as in 18453-2.patch.

[azaozz]

In [18747]:

Postpone warnings when WP_DEBUG and WP_DEBUG_DISPLAY are set, see #18453

[nacin]

There should have been more discussion before [18747]. These are going to flood the dashboards of users, not developers.

Simply pointing them to codex/Debugging_in_WordPress in the notice itself is enough. As agreed, we will not be linking to individual plugins. (Mind you, I maintain one of those plugins, contribute to the other, wrote _doing_it_wrong() originally, and largely care for debugging and deprecated code in core.)

In IRC, I objected to this. I remain -1 and suggest further discussion. Would like to see westi in particular weigh in on this.

[scribu]

Replying to azaozz:

In [18747]:

Postpone warnings when WP_DEBUG and WP_DEBUG_DISPLAY are set, see #18453

This seems backwards to me. Shouldn't warnings be postponed if WP_DEBUG_DISPLAY is not set?

Also, the way it's currently done, _doing_it_wrong() calls are limited to the admin area and before 'admin_notices'.

[scribu]

Worst of all, you loose the ability to do backtraces through a custom error handler.

So, definitely -1 from me.

[nacin]

Talked to azaozz, we'll tweak this tomorrow.

[westi]

In [18752]:

Revert [18747] until we can discuss it further. See #18453.

[westi]

I don't see why we need to do this at all.

Improve the copy in the message to promote the plugins maybe but I think we have much more important things to focus on.

[azaozz]

Replying to westi:

I don't see why we need to do this at all.

This ticket was meant to enhance the "first time" experience for new or beginner developers starting to work with WordPress. We care a lot about first time user experience but kind of ignore the new plugin and theme authors.

It was meant to prompt them to install a debugging plugin and not break the output in the process. By default most PHP installations show errors instead of logging them. This was meant to cover these cases.

User case:

• install LAMP, MAMP, WAMP, etc.
• add WordPress, make an account, etc.
• add a plugin that would trigger deprecated or doing_it_wrong.

At this point if the warning triggers before 'init' the new developer will see our warning message followed by many "headers already sent...". If it triggers at 'init', WP will load but all ajax will be broken (as the warning message is printed before the expected ajax return).

We chatted with @nacin late yesterday night and agreed that the current code is not the best way to handle this, but I still think we need to have something to cover the default PHP installs when outputting the deprecated and doing_it_wrong warnings.

[chrisbliss18]

@azaozz

Agreed.

Just because the current design may work for those commenting on this ticket doesn't mean that it will work for novice or even some intermediate developers. Having a message pop up that will do more to confuse rather than inform new developers is not a good design.

I still think that the message should contain as much useful information as possible, such as giving details about where the problem came from, but I am willing to give up that idea if we can at least give the user details about how to find out where the problem is originating.

[azaozz]

In [18923]:

Add link to the codex in the doing_it_wrong notices, see #18453

[nacin]

In [19044]:

In _doing_it_wrong(), don't append the Debugging_in_WordPress message until we go to print a message. Send a clean message to the action. see #18453.