Would like mod_perl 1.29 to include more information on fatal errors

Hello,

We are running Apache/1.3.37 with mod_perl/1.29. We use the regular
mod_perl API to install custom access, authentication, authorization,
fixup, content, and logging handlers.

Once in a great while we run into random "Undefined subroutine
XX::Clients::YY::ContentHandler::handler called.\n" messages, where XX
represents our internal namespace for our packages and YY a specific
client.

A snippet of typical Apache configuration is something like this for a
virtual host:

PerlAuthenHandler XX::Account::AuthenHandler
PerlAuthzHandler XX::Account::AuthzHandler

SetHandler perl-script
PerlHandler XX::Clients::YY::ContentHandler


When we get the undefined subroutine message, it looks like this:

[Wed Sep 2 08:43:30 2009] [error] Undefined subroutine &XX::Clients::YY::ContentHandler::handler called.\n

The user sees a "white page" when this happens. No error message... but
no content either. Usually hitting refresh will bring up the page
they wanted, but it's obviously bad to have users experience "random"
empty/white pages.

The literal backslash and literal n are both (literally) in the logged
message in the error log, which is why I think this error is coming
from Perl and is just getting passed through by mod_perl to Apache;
nothing is interpreting the line and translating the two characters
"\" and "n" into a newline.

Usually we can track this down in our QA and production environments
to a module that relies on a different module that we failed to "use."
It works most of the time because some earlier hit caused the Apache
process to load one of our custom modules that in-turn use'd the
module the later module referenced, so it was in coincidentally in
memory the vast majority of the time it was referenced. The problem is
when a clean/new Apache process served the faulty module *first*,
before serving any other custom content, and then we would get the
"Undefined subroutine" type of message.

However, we've checked everything we can think of and we're unable to
track down the problem in a particular set of custom modules for a
client where this problem keeps happening for a small percentage of
the hits. Sometimes the problem will also happen in our development
environment, but then it is usually due to a compilation error (like
bad syntax) where StatINC tried to load the new version of the module
from disk and it failed to compile. When that happens, there is
nothing in memory for that module so the "handler" function is not
defined. Once the syntax error is fixed the problem goes away (in our
development environment; this cause of the problem is never in our QA
or production environments)

We've ran out of ideas on why the main "handler" method--in a module
that mod_perl should be loading directly--would generate this message.
There are no preceeding error messages that we can attribute this
error to. We are hoping if we spat out more information about the
request (URI, params, etc) and the state of the process (pid, modules
loaded, etc) we might be able to see what is going on and fix the
problem.

I would like to know if someone has a patch that will dump out more
information about the hit, such as the requested URI, any parameters
that are passed, what perl modules are in memory, the process ID, or
anything at all that might help.

I'm rusty on my C and I've never dug into mod_perl guts before, so I'm
not sure where to even begin to look at adding the output of
information myself on a fatal error (one that prevents a properly
handled response). From what I can tell, it seems like mod_perl is
taking an error from PERL and passing it directly to Apache's error
logging mechanism. I'd like to intercept that call and dump out the
extra information as well as the original error.

Any guidance on patching/hacking mod_perl 1.29 to have more verbose
error messages would be greatly appreciated.

--
James
Funny quotes: "There are 10 types of people in the world.
Those who understand binary, and those who don't." -- Unknown
"A computer once beat me at chess, but it was no match for me at
kick boxing." -- Emo Philips

Re: Would like mod_perl 1.29 to include more information on fatal

On Thu, Sep 3, 2009 at 11:32 AM, James Olsen wrote:
> I would like to know if someone has a patch that will dump out more
> information about the hit, such as the requested URI, any parameters
> that are passed, what perl modules are in memory, the process ID, or
> anything at all that might help.
>
> I'm rusty on my C and I've never dug into mod_perl guts before, so I'm
> not sure where to even begin to look at adding the output of
> information myself on a fatal error (one that prevents a properly
> handled response).

You could:
- Make s $SIG{__DIE__} handler
- Wrap your application in an eval {}

The data you want is available from either the standard apache log
formats or perl code in Apache::Status, so there's no need to worry
about writing C here.

- Perrin

Re: Would like mod_perl 1.29 to include more information on fatal errors

Hello Perrin,

Thank you for your response.

PH> You could:
PH> - Make s $SIG{__DIE__} handler
PH> - Wrap your application in an eval {}

PH> The data you want is available from either the standard apache log
PH> formats or perl code in Apache::Status, so there's no need to worry
PH> about writing C here.

The trouble is, our code isn't getting invoked at all. Mod_perl (or
something lower-level like that) is dying complaining that our code
can't be found on the hits where this happens. As an aside, we already
have similar eval traps, including one over the main handler code in
an attempt to provide the best error handling for our clients as
possible.

A mod_perl handler is set up (in apache conf), such as a content
handler, like this:
PerlHandler XX::Clients::YY::ContentHandler

When that resource is invoked by via a web request (GET or POST,
usually), mod_perl will load the module
"XX::Clients::YY::ContentHandler" and then attempt to call a method
named "handler." It is this invocation of "handler" by mod_perl that
is randomly failing and we're trying to find more information about.

We added an "ErrorDocument 500" statement in the Apache config, and
set it to a CGI program, which dumps out the symbol table using
Devel::Symdump as well as dumping out %INC.

The symbol dump shows (only relevant lines copied, there were hundreds
of lines output)

arrays
[nothing related to this]
functions
XX::Clients::YY::ContentHandler::handler
hashes
[nothing related to this]
ios
[nothing related to this]
packages
XX::Clients::YY
XX::Clients::YY::ContentHandler
scalars
XX::Clients::YY::
XX::Clients::YY::ContentHandler::
XX::Clients::YY::ContentHandler::AUTOLOAD
XX::Clients::YY::ContentHandler::DESTROY
XX::Clients::YY::ContentHandler::handler

**NOTE** The last item listed under "functions" is is what mod_perl
complained was undefined in the error log; so it seems like it was
partially defined (since some things exist for it in the symbol
table).

%INC shows many, many modules, with the module's relative path as the
key and the full path as the value. However, NOTHING exists in it
regarding XX::Clients::YY, even though there are entries for other
working clients and has normal entries on normal hits.

------------------------------------------------------------ ---------

When everything is working normally, here is what we see in the Symbol
table related to our module for client YY (tons of stuff related to
this module, as before, the unrelated content was omitted from this
post):

arrays
XX::Clients::YY::ContentHandler::EXPORT
XX::Clients::YY::ContentHandler::EXPORT_FAIL
XX::Clients::YY::ContentHandler::ISA
XX::Clients::YY::ContentHandler::SUPER::ISA
functions
XX::Clients::YY::Custom::display_home
XX::Clients::YY::ContentHandler::_find_element
XX::Clients::YY::ContentHandler::_fix_menu
XX::Clients::YY::ContentHandler::_get_category_ids
XX::Clients::YY::ContentHandler::_num_spreads
XX::Clients::YY::ContentHandler::_record_audit_trail
XX::Clients::YY::ContentHandler::add_to_cart
XX::Clients::YY::ContentHandler::ceil
XX::Clients::YY::ContentHandler::check_children
XX::Clients::YY::ContentHandler::classes
XX::Clients::YY::ContentHandler::cleanup
XX::Clients::YY::ContentHandler::display_approval
XX::Clients::YY::ContentHandler::display_asset_management
XX::Clients::YY::ContentHandler::display_asset_search
XX::Clients::YY::ContentHandler::display_asset_search_cart
XX::Clients::YY::ContentHandler::display_asset_search_result s
XX::Clients::YY::ContentHandler::display_asset_tree
XX::Clients::YY::ContentHandler::display_customized_preview
XX::Clients::YY::ContentHandler::display_dealer_info
XX::Clients::YY::ContentHandler::display_export
XX::Clients::YY::ContentHandler::display_forgot_password
XX::Clients::YY::ContentHandler::display_load
XX::Clients::YY::ContentHandler::display_photo
XX::Clients::YY::ContentHandler::display_product_results
XX::Clients::YY::ContentHandler::display_profile
XX::Clients::YY::ContentHandler::display_resize
XX::Clients::YY::ContentHandler::display_saved_documents
XX::Clients::YY::ContentHandler::display_step
XX::Clients::YY::ContentHandler::display_text
XX::Clients::YY::ContentHandler::display_tree
XX::Clients::YY::ContentHandler::display_welcome
XX::Clients::YY::ContentHandler::display_work_area
XX::Clients::YY::ContentHandler::do_nothing
XX::Clients::YY::ContentHandler::document_export
XX::Clients::YY::ContentHandler::download_zip
XX::Clients::YY::ContentHandler::fields
XX::Clients::YY::ContentHandler::funcs
XX::Clients::YY::ContentHandler::generate_preview
XX::Clients::YY::ContentHandler::handler
XX::Clients::YY::ContentHandler::new
XX::Clients::YY::ContentHandler::process_approval
XX::Clients::YY::ContentHandler::process_approval_request
XX::Clients::YY::ContentHandler::process_asset_category
XX::Clients::YY::ContentHandler::process_asset_search
XX::Clients::YY::ContentHandler::process_category
XX::Clients::YY::ContentHandler::process_category_select_pul ldown
XX::Clients::YY::ContentHandler::process_creator
XX::Clients::YY::ContentHandler::process_dealer_info
XX::Clients::YY::ContentHandler::process_email_cart
XX::Clients::YY::ContentHandler::process_empty_cart
XX::Clients::YY::ContentHandler::process_export
XX::Clients::YY::ContentHandler::process_export_cart
XX::Clients::YY::ContentHandler::process_images_lookup
XX::Clients::YY::ContentHandler::process_images_search
XX::Clients::YY::ContentHandler::process_load
XX::Clients::YY::ContentHandler::process_photo
XX::Clients::YY::ContentHandler::process_profile
XX::Clients::YY::ContentHandler::process_save
XX::Clients::YY::ContentHandler::process_step
XX::Clients::YY::ContentHandler::process_text
XX::Clients::YY::ContentHandler::remove_from_cart
XX::Clients::YY::ContentHandler::start_adcreator
hashes
XX::Clients::YY::Custom::funcs
ios
XX::Clients::YY::ContentHandler::FILE
XX::Clients::YY::ContentHandler::PHOTO
packages
XX::Clients::YY
XX::Clients::YY::Config
XX::Clients::YY::Custom
XX::Clients::YY::ContentHandler
XX::Clients::YY::ContentHandler::::ISA::CACHE
XX::Clients::YY::ContentHandler::SUPER
scalars
XX::Clients::YY::
XX::Clients::YY::Config::
XX::Clients::YY::Config::BEGIN
XX::Clients::YY::Config::base_path
XX::Clients::YY::Config::base_url
XX::Clients::YY::Config::client_assets
XX::Clients::YY::Config::constrain
XX::Clients::YY::Config::data_path
XX::Clients::YY::Config::download_path
XX::Clients::YY::Config::download_url
XX::Clients::YY::Config::help
XX::Clients::YY::Config::logos_path
XX::Clients::YY::Config::ports
XX::Clients::YY::Config::preview_path
XX::Clients::YY::Config::preview_url
XX::Clients::YY::Config::remember_me_cookie
XX::Clients::YY::Config::saved
XX::Clients::YY::Config::template_path
XX::Clients::YY::Config::unprotected_path
XX::Clients::YY::Custom::
XX::Clients::YY::Custom::VERSION
XX::Clients::YY::Custom::account_type
XX::Clients::YY::Custom::adcreator_name
XX::Clients::YY::Custom::can
XX::Clients::YY::Custom::ccs_domain
XX::Clients::YY::Custom::check_welcome
XX::Clients::YY::Custom::creator_obj
XX::Clients::YY::Custom::display_approval
XX::Clients::YY::Custom::display_asset_category
XX::Clients::YY::Custom::display_asset_management
XX::Clients::YY::Custom::display_asset_search
XX::Clients::YY::Custom::display_asset_search_cart
XX::Clients::YY::Custom::display_asset_search_results
XX::Clients::YY::Custom::display_asset_tree
XX::Clients::YY::Custom::display_customized_preview
XX::Clients::YY::Custom::display_dealer_info
XX::Clients::YY::Custom::display_export
XX::Clients::YY::Custom::display_forgot_password
XX::Clients::YY::Custom::display_home
XX::Clients::YY::Custom::display_load
XX::Clients::YY::Custom::display_photo
XX::Clients::YY::Custom::display_product_results
XX::Clients::YY::Custom::display_profile
XX::Clients::YY::Custom::display_resize
XX::Clients::YY::Custom::display_saved_documents
XX::Clients::YY::Custom::display_step
XX::Clients::YY::Custom::display_text
XX::Clients::YY::Custom::display_tree
XX::Clients::YY::Custom::display_welcome
XX::Clients::YY::Custom::document_export
XX::Clients::YY::Custom::domain
XX::Clients::YY::Custom::funcs
XX::Clients::YY::Custom::generate_preview
XX::Clients::YY::Custom::global_session
XX::Clients::YY::Custom::handler_pre_method_call
XX::Clients::YY::Custom::highlight_elements_in_preview
XX::Clients::YY::Custom::hit_debug
XX::Clients::YY::Custom::import
XX::Clients::YY::Custom::load_account_package
XX::Clients::YY::Custom::load_account_params
XX::Clients::YY::Custom::preview_horizontal_size
XX::Clients::YY::Custom::preview_path
XX::Clients::YY::Custom::preview_quality
XX::Clients::YY::Custom::preview_resolution
XX::Clients::YY::Custom::preview_size_percent
XX::Clients::YY::Custom::preview_units
XX::Clients::YY::Custom::preview_vertical_size
XX::Clients::YY::Custom::process_approval
XX::Clients::YY::Custom::process_approval_request
XX::Clients::YY::Custom::process_asset_search
XX::Clients::YY::Custom::process_category
XX::Clients::YY::Custom::process_creator
XX::Clients::YY::Custom::process_dealer_info
XX::Clients::YY::Custom::process_email_cart
XX::Clients::YY::Custom::process_export
XX::Clients::YY::Custom::process_load
XX::Clients::YY::Custom::process_photo
XX::Clients::YY::Custom::process_profile
XX::Clients::YY::Custom::process_save
XX::Clients::YY::Custom::process_step
XX::Clients::YY::Custom::process_text
XX::Clients::YY::Custom::r
XX::Clients::YY::Custom::use_apache_filter
XX::Clients::YY::ContentHandler::
XX::Clients::YY::ContentHandler::::ISA::CACHE::
XX::Clients::YY::ContentHandler::AUTOLOAD
XX::Clients::YY::ContentHandler::BEGIN
XX::Clients::YY::ContentHandler::DESTROY
XX::Clients::YY::ContentHandler::EXPORT
XX::Clients::YY::ContentHandler::EXPORT_FAIL
XX::Clients::YY::ContentHandler::FILE
XX::Clients::YY::ContentHandler::ISA
XX::Clients::YY::ContentHandler::PHOTO
XX::Clients::YY::ContentHandler::SUPER::
XX::Clients::YY::ContentHandler::SUPER::ISA
XX::Clients::YY::ContentHandler::SUPER::ContentHandler
XX::Clients::YY::ContentHandler::SUPER::new
XX::Clients::YY::ContentHandler::_account_load
XX::Clients::YY::ContentHandler::_find_element
XX::Clients::YY::ContentHandler::_fix_menu
XX::Clients::YY::ContentHandler::_generate_preview
XX::Clients::YY::ContentHandler::_get_category_ids
XX::Clients::YY::ContentHandler::_init
XX::Clients::YY::ContentHandler::_num_spreads
XX::Clients::YY::ContentHandler::_record_audit_trail
XX::Clients::YY::ContentHandler::a
XX::Clients::YY::ContentHandler::account_type
XX::Clients::YY::ContentHandler::adcreator
XX::Clients::YY::ContentHandler::adcreator_name
XX::Clients::YY::ContentHandler::add_attribute
XX::Clients::YY::ContentHandler::add_to_cart
XX::Clients::YY::ContentHandler::b
XX::Clients::YY::ContentHandler::can
XX::Clients::YY::ContentHandler::ccs_domain
XX::Clients::YY::ContentHandler::ceil
XX::Clients::YY::ContentHandler::check_children
XX::Clients::YY::ContentHandler::classes
XX::Clients::YY::ContentHandler::cleanup
XX::Clients::YY::ContentHandler::creator_obj
XX::Clients::YY::ContentHandler::display_approval
XX::Clients::YY::ContentHandler::display_asset_management
XX::Clients::YY::ContentHandler::display_asset_search
XX::Clients::YY::ContentHandler::display_asset_search_cart
XX::Clients::YY::ContentHandler::display_asset_search_result s
XX::Clients::YY::ContentHandler::display_asset_tree
XX::Clients::YY::ContentHandler::display_customized_preview
XX::Clients::YY::ContentHandler::display_dealer_info
XX::Clients::YY::ContentHandler::display_export
XX::Clients::YY::ContentHandler::display_forgot_password
XX::Clients::YY::ContentHandler::display_load
XX::Clients::YY::ContentHandler::display_photo
XX::Clients::YY::ContentHandler::display_product_results
XX::Clients::YY::ContentHandler::display_profile
XX::Clients::YY::ContentHandler::display_resize
XX::Clients::YY::ContentHandler::display_saved_documents
XX::Clients::YY::ContentHandler::display_step
XX::Clients::YY::ContentHandler::display_text
XX::Clients::YY::ContentHandler::display_tree
XX::Clients::YY::ContentHandler::display_welcome
XX::Clients::YY::ContentHandler::display_work_area
XX::Clients::YY::ContentHandler::do_nothing
XX::Clients::YY::ContentHandler::document_export
XX::Clients::YY::ContentHandler::domain
XX::Clients::YY::ContentHandler::download_zip
XX::Clients::YY::ContentHandler::fields
XX::Clients::YY::ContentHandler::funcs
XX::Clients::YY::ContentHandler::generate_preview
XX::Clients::YY::ContentHandler::global_session
XX::Clients::YY::ContentHandler::handler
XX::Clients::YY::ContentHandler::handler_pre_method_call
XX::Clients::YY::ContentHandler::highlight_elements_in_previ ew
XX::Clients::YY::ContentHandler::hit_debug
XX::Clients::YY::ContentHandler::import
XX::Clients::YY::ContentHandler::isa
XX::Clients::YY::ContentHandler::load_account_package
XX::Clients::YY::ContentHandler::load_account_params
XX::Clients::YY::ContentHandler::new
XX::Clients::YY::ContentHandler::preview_horizontal_size
XX::Clients::YY::ContentHandler::preview_path
XX::Clients::YY::ContentHandler::preview_quality
XX::Clients::YY::ContentHandler::preview_resolution
XX::Clients::YY::ContentHandler::preview_size_percent
XX::Clients::YY::ContentHandler::preview_units
XX::Clients::YY::ContentHandler::preview_vertical_size
XX::Clients::YY::ContentHandler::process_approval
XX::Clients::YY::ContentHandler::process_approval_request
XX::Clients::YY::ContentHandler::process_asset_category
XX::Clients::YY::ContentHandler::process_asset_search
XX::Clients::YY::ContentHandler::process_category
XX::Clients::YY::ContentHandler::process_category_select_pul ldown
XX::Clients::YY::ContentHandler::process_creator
XX::Clients::YY::ContentHandler::process_dealer_info
XX::Clients::YY::ContentHandler::process_email_cart
XX::Clients::YY::ContentHandler::process_empty_cart
XX::Clients::YY::ContentHandler::process_export
XX::Clients::YY::ContentHandler::process_export_cart
XX::Clients::YY::ContentHandler::process_images_lookup
XX::Clients::YY::ContentHandler::process_images_search
XX::Clients::YY::ContentHandler::process_load
XX::Clients::YY::ContentHandler::process_photo
XX::Clients::YY::ContentHandler::process_profile
XX::Clients::YY::ContentHandler::process_save
XX::Clients::YY::ContentHandler::process_step
XX::Clients::YY::ContentHandler::process_text
XX::Clients::YY::ContentHandler::r
XX::Clients::YY::ContentHandler::remove_from_cart
XX::Clients::YY::ContentHandler::start_adcreator
XX::Clients::YY::ContentHandler::test_attribute
XX::Clients::YY::ContentHandler::use_apache_filter
main::_ main::_ main::_
and here is what we normally see in %INC:
'XX/Clients/YY/Config.pm' => '/usr/local/lib/perl5/site_perl/5.8.6/XX/Clients/YY/Config.p m',
'XX/Clients/YY/Custom.pm' => '/usr/local/lib/perl5/site_perl/5.8.6/XX/Clients/YY/Custom.p m',
'XX/Clients/YY/ContentHandler.pm' => '/usr/local/lib/perl5/site_perl/5.8.6/XX/Clients/YY/ContentH andler.pm',

============================================================ ================

So, to recap:

Normally, %INC and the perl symbol table has plenty of data about our
module XX::Clients::YY::ContentHandler and the "handler" method is
invoked just fine by mod_perl.

On some "random" (we have not been able to detect an occurrence pattern
or reliably reproduce the problem) hits, we get an error saying
"handler" is undefined. When this happens, %INC hash is missing the
module and the symbol table has some information but is lacking the
vast majority of it.

Mod_perl/perl/apache/something other than us, not us, controls the
loading and execution of our module, and we need help tracing down and
fixing this problem.

Does anyone have any ideas what would possibly cause items to be in
the symbol table for a module, but the module wouldn't be in %INC or
seemingly in memory at all (since we got an 'Undefined subroutine'
error when mod_perl tried to invoke the "handler" method)?

Please, if anyone has more ideas on things to try, we'd be delighted
to hear them.

--
James
"A computer once beat me at chess, but it was no match for me at
kick boxing." -- Emo Philips
"There are 10 types of people in the world. Those who understand
binary, and those who don't." -- Unknown

Re: Would like mod_perl 1.29 to include more information on fatal

On Fri, Sep 4, 2009 at 12:00 PM, James Olsen wrote:
> The trouble is, our code isn't getting invoked at all. Mod_perl (or
> something lower-level like that) is dying complaining that our code
> can't be found on the hits where this happens.

Did you try $SIG{__DIE__}? It's a global setting for that perl
interpreter. I expect it will catch this. But it sounds like you
already got what you needed from your 500 intercept.

> Does anyone have any ideas what would possibly cause items to be in
> the symbol table for a module, but the module wouldn't be in %INC or
> seemingly in memory at all (since we got an 'Undefined subroutine'
> error when mod_perl tried to invoke the "handler" method)?

Sure. You can just say $XX::Clients::YY::ContentHandler::foo = 1 to
put something in the symbol table. It doesn't mean the module is
loaded.

I suggest you set your logging so you can see the exact set of
requests the process received in order (by following the PID), before
having this problem, and then try to recreate it by sending those same
requests with a WWW::Mechanize script. Maybe that will show you how
your code skipped loading this module.

- Perrin