Page MenuHomePhabricator

Service utils logger fails with message containing stack trace
Closed, ResolvedPublicBUG REPORT

Description

Description

serviceUtil.logger.log() failed with the following error:

Logger.log failed: TypeError: Cannot read properties of undefined (reading '0')
     at WikimediaEcsFormatMiddleware.transform (/srv/service/node_modules/@wikimedia/service-utils/dist/index.js:29:39)
     at Format.transform (/srv/service/node_modules/logform/combine.js:20:24)
     at DerivedLogger._transform (/srv/service/node_modules/winston/lib/winston/logger.js:314:29)
     at Transform._read (/srv/service/node_modules/readable-stream/lib/_stream_transform.js:166:10)
     at Transform._write (/srv/service/node_modules/readable-stream/lib/_stream_transform.js:155:83)
     at doWrite (/srv/service/node_modules/readable-stream/lib/_stream_writable.js:390:139)
     at writeOrBuffer (/srv/service/node_modules/readable-stream/lib/_stream_writable.js:381:5)
     at Writable.write (/srv/service/node_modules/readable-stream/lib/_stream_writable.js:302:11)
     at DerivedLogger.value (/srv/service/node_modules/winston/lib/winston/logger.js:67:18)
     at DerivedLogger.log (/srv/service/node_modules/winston/lib/winston/logger.js:225:14)

The log method is being called with the following args:

[
   'error',
   {
      message: 'Otherwise Unhandled error 500: {"message":"500: internal_error","name":"HTTPError","stack":"PayloadTooLargeError: request entity too large\\n    at readStream (/srv/service/node_modules/raw-body/index.js:163:17)\\n    at getRawBody (/srv/service/node_modules/raw-body/index.js:116:12)\\n    at read (/srv/service/node_modules/body-parser/lib/read.js:79:3)\\n    at rawParser (/srv/service/node_modules/body-parser/lib/types/raw.js:81:5)\\n    at Layer.handle [as handle_request] (/srv/service/node_modules/express/lib/router/layer.js:95:5)\\n    at trim_prefix (/srv/service/node_modules/express/lib/router/index.js:328:13)\\n    at /srv/service/node_modules/express/lib/router/index.js:286:9\\n    at Function.process_params (/srv/service/node_modules/express/lib/router/index.js:346:12)\\n    at next (/srv/service/node_modules/express/lib/router/index.js:280:10)\\n    at urlencodedParser (/srv/service/node_modules/body-parser/lib/types/urlencoded.js:103:7)","status":500,"type":"internal_error","detail":"request entity too large"}',
      level: 'error',
      serviceName: 'function-evaluator',
      [Symbol(level)]: 'error'
   }
]

Details

Related Changes in Gerrit:
Related Changes in GitLab:
TitleReferenceAuthorSource BranchDest Branch
Update service-utils from 1.3.0 to 1.3.1repos/abstract-wiki/wikifunctions/function-orchestrator!365ecarggrace/T393152/bump-sUtils-versionmain
Update service-utils from 1.3.0 to 1.3.1repos/abstract-wiki/wikifunctions/function-evaluator!344ecarggrace/T393152/bump-sUtils-versionmain
Optional chain logging request propertiesrepos/data-engineering/service-utils!13tchinoption-chain-logging-request-propertiesmain
Customize query in GitLab

Event Timeline

The log that is causing the issue is in function-evaluator/lib/utils.js line 209 error handler:

		// log the error
		const component = ( errObj.component ? errObj.component : errObj.status );
		// Encode the error object into JSON so the log doesn't just show `500: [object Object]`
		const message = `Otherwise Unhandled error ${ component }: ${ JSON.stringify( errForLog( errObj ) ) }`;
		( req.logger || app.logger ).log( level, { message: message } );

The line throwing is url.path = info.request.params[0]; — and indeed, our request object won't have any params, as we're POST-only in the evaluator. Maybe that needs to be set to {} by default? Or we're doing something wrongly?

@ecarg Should be this one in "In Engineering" Column?

Patches updating our version to 1.3.1 (thanks!) merging; will deploy on Wednesday to check how well they address the issue.

Change #1145863 had a related patch set uploaded (by Jforrester; author: Jforrester):

[operations/deployment-charts@master] wikifunctions: Update evaluators from 2025-05-07-003410 to 2025-05-12-235119

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

Change #1145864 had a related patch set uploaded (by Jforrester; author: Jforrester):

[operations/deployment-charts@master] wikifunctions: Update orchestrator from 2025-05-06-142345 to 2025-05-14-112404

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

Change #1145863 merged by jenkins-bot:

[operations/deployment-charts@master] wikifunctions: Update evaluators from 2025-05-07-003410 to 2025-05-12-235119

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

Change #1145864 merged by jenkins-bot:

[operations/deployment-charts@master] wikifunctions: Update orchestrator from 2025-05-06-142345 to 2025-05-14-112404

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

No signs of this log error for the past two weeks