When logging an exception in Logstash as a PSR-3 context parameter, the trace does not include class/method names
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	Tgr
	Nov 22 2016, 5:00 AM

Description

E.g. in https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2016.11.22/mediawiki/?id=AViJ_E2IPSU6VDGXPCmC
(which is created by something like $logger->warning( 'foo', [ 'exception' => new Exception( 'bar' ) ] );) th field is exception.trace

/srv/mediawiki/php-1.29.0-wmf.3/includes/user/User.php:5123, /srv/mediawiki/php-1.29.0-wmf.3/includes/user/User.php:2766, /srv/mediawiki/php-1.29.0-wmf.3/includes/context/RequestContext.php:364, /srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:207, /srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:169, /srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:112, /srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:139, /srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:2110, /srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:2075, /srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:1290, /srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:441, /srv/mediawiki/php-1.29.0-wmf.3/includes/OutputPage.php:1872, /srv/mediawiki/php-1.29.0-wmf.3/includes/OutputPage.php:1895, /srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilter.class.php:759, /srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilter.class.php:947, /srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilterPreAuthenticationProvider.php:41, /srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilterPreAuthenticationProvider.php:13, /srv/mediawiki/php-1.29.0-wmf.3/includes/auth/AuthManager.php:1648, /srv/mediawiki/php-1.29.0-wmf.3/includes/Setup.php:866, /srv/mediawiki/php-1.29.0-wmf.3/includes/WebStart.php:137, /srv/mediawiki/php-1.29.0-wmf.3/index.php:40, /srv/mediawiki/w/index.php:3

which is not exactly user-friendly. It should look more like this:

#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /vagrant/mediawiki/includes/WebResponse.php(45): header(string, boolean)
#2 /vagrant/mediawiki/extensions/XAnalytics/XAnalytics.class.php(67): WebResponse->header(string, boolean)

The behavior seems to be coming from NormalizerFormatter::normalizeException (which LogstashFormatter inherits).

Details

	Subject	Repo	Branch	Lines +/-
	Use custom LogstashFormatter	operations/mediawiki-config	master	+1 -1
	Improve logging of exceptions which are not thrown but attached to context	mediawiki/core	master	+28 -0

Customize query in gerrit

Related Objects
Search...

		Status	Subtype	Assigned	Task
		Open		None	T157850 Interacting with Wikimedia logs should be a pleasant experience
		Resolved		Tgr	T151290 When logging an exception in Logstash as a PSR-3 context parameter, the trace does not include class/method names

Event Timeline

Tgr created this task.Nov 22 2016, 5:00 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 22 2016, 5:00 AM

As you have noted, the serialization of the exception comes from the upstream Monolog library.

  "exception": {
    "class": "Exception",
    "message": "User::loadFromSession called before the end of Setup.php",
    "code": 0,
    "file": "/srv/mediawiki/php-1.29.0-wmf.3/includes/user/User.php:374",
    "trace": [
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/user/User.php:5123",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/user/User.php:2766",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/context/RequestContext.php:364",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:207",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:169",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:112",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/StubObject.php:139",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:2110",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:2075",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:1290",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/parser/Parser.php:441",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/OutputPage.php:1872",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/OutputPage.php:1895",
      "/srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilter.class.php:759",
      "/srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilter.class.php:947",
      "/srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilterPreAuthenticationProvider.php:41",
      "/srv/mediawiki/php-1.29.0-wmf.3/extensions/AbuseFilter/AbuseFilterPreAuthenticationProvider.php:13",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/auth/AuthManager.php:1648",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/Setup.php:866",
      "/srv/mediawiki/php-1.29.0-wmf.3/includes/WebStart.php:137",
      "/srv/mediawiki/php-1.29.0-wmf.3/index.php:40",
      "/srv/mediawiki/w/index.php:3"
    ]
  }
},

The pretty printed version you reference comes from MWExceptionHandler::prettyPrintTrace()'s output of a MWExceptionHandler::getRedactedTrace() generated backtrace. The display of a trace in Kibana is not going to look like a custom pretty print unless we stop stop storing the trace data as structured data. Even then I think Kibana folds newlines as normal whitespace when shown in the table view. With a custom Monolog formatter we could store a different form of trace such as the one generated by MWExceptionHandler::getRedactedTrace().

Newlines do seem to be preserved up to a truncation limit as can be seen in wfDebug channel messages.

Change 323446 had a related patch set uploaded (by Gergő Tisza):
Improve logging of exceptions which are not thrown but attached to context

https://gerrit.wikimedia.org/r/323446

gerritbot added a project: Patch-For-Review.Nov 24 2016, 8:58 PM

Change 323492 had a related patch set uploaded (by Gergő Tisza):
Use custom LogstashFormatter

https://gerrit.wikimedia.org/r/323492

Tgr added a parent task: T157850: Interacting with Wikimedia logs should be a pleasant experience.Feb 11 2017, 1:39 AM

Tgr mentioned this in T136849: normalized_message is a JSON dump of the whole event for exceptions in beta logstash.Feb 22 2017, 1:22 AM

Change 323446 merged by jenkins-bot:
Improve logging of exceptions which are not thrown but attached to context

https://gerrit.wikimedia.org/r/323446

ReleaseTaggerBot added projects: MW-1.29-release (WMF-deploy-2017-02-28_(1.29.0-wmf.14)), MW-1.29-release-notes.Feb 24 2017, 1:00 PM

Change 323492 merged by jenkins-bot:
[operations/mediawiki-config] Use custom LogstashFormatter

https://gerrit.wikimedia.org/r/323492

Mentioned in SAL (#wikimedia-operations) [2017-03-15T18:19:17Z] <legoktm@tin> Synchronized wmf-config/logging.php: Use custom LogstashFormatter - T145133, T151290 (duration: 00m 42s)

Fixed:

exception.trace
#0 /srv/mediawiki/php-1.29.0-wmf.15/includes/session/SessionManager.php(637): MediaWiki\Session\SessionProvider->mergeMetadata(array, array)
#1 /srv/mediawiki/php-1.29.0-wmf.15/includes/session/SessionManager.php(506): MediaWiki\Session\SessionManager->loadSessionInfoFromStore(MediaWiki\Session\SessionInfo, WebRequest)
#2 /srv/mediawiki/php-1.29.0-wmf.15/includes/session/SessionManager.php(190): MediaWiki\Session\SessionManager->getSessionInfoForRequest(WebRequest)
#3 /srv/mediawiki/php-1.29.0-wmf.15/includes/WebRequest.php(735): MediaWiki\Session\SessionManager->getSessionForRequest(WebRequest)
#4 /srv/mediawiki/php-1.29.0-wmf.15/includes/session/SessionManager.php(129): WebRequest->getSession()
#5 /srv/mediawiki/php-1.29.0-wmf.15/includes/Setup.php(728): MediaWiki\Session\SessionManager::getGlobalSession()
#6 /srv/mediawiki/php-1.29.0-wmf.15/includes/WebStart.php(139): include(string)
#7 /srv/mediawiki/php-1.29.0-wmf.15/api.php(38): include(string)
#8 /srv/mediawiki/w/api.php(3): include(string)
#9 {main}

(TIL: you can find events which set a certain fields in Kibana with _exists_:<field>)

fgiunchedi added a project: observability.Aug 19 2019, 2:27 PM

When logging an exception in Logstash as a PSR-3 context parameter, the trace does not include class/method namesClosed, ResolvedPublicActions

Description

Details

Related ObjectsSearch...

Event Timeline

When logging an exception in Logstash as a PSR-3 context parameter, the trace does not include class/method names
Closed, ResolvedPublic
Actions

Related Objects
Search...