Ensure that messages logged to stackdriver error handling match the stack format
Categories
(Taskcluster :: Services, enhancement)
Tracking
(Not tracked)
People
(Reporter: dustin, Assigned: dustin)
Details
Attachments
(1 file)
Screenshot_2019-05-16 Logs Viewer - heroku-logging - Google Cloud Platform.png
https://console.cloud.google.com/errors/CMuy9diB767SgwE?time=P7D&project=heroku-logging shows a bunch of errors that have stacks like this:
EntityAlreadyExistsError: The specified entity already exists.
RequestId:f735dd2e-c002-00b7-4b30-fa6980000000
Time:2019-04-24T00:01:28.4964467Z
at /app/node_modules/fast-azure-storage/lib/table.js:401:27
at tryCallOne (/app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:37:12)
at /app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:123:15
at flush (/app/node_modules/asap/raw.js:50:29)
at process._tickCallback (internal/process/next_tick.js:61:11)
Stackdriver uses a pattern-matching approach to find a V8 stack within that, and expects only one line of error message before the stack begins. So its notion of the error line is "Time:..", which isn't helpful :)
This message comes from fast-azure-storage, which is just copying them from Azure. So one thing to fix is to strip that Azure error message to only its first line.
Another thing to fix is, we should ensure that when creating jsonPayload.message (which is, I think, where stackdriver errors is getting the stack?) for an error, we only include the first line of the exception.
|
Assignee | |
Comment 1•7 years ago
|
||
https://enterprise.google.com/supportcenter/managecases#Case/001000000040sBR/U-19147894 covers
Errors:
* data.origin.revision should NOT be shorter than 40 characters
* data.origin should NOT have additional properties: "pushLogID"
* data.origin.kind should be equal to one of the allowed values
* data.origin.revision should NOT be shorter than 40 characters
* data.origin should match exactly one schema in oneOf
at PulsePublisher._validateMessage (/app/libraries/pulse/src/publisher.js:376:13)
which is also a multiline error, without much of use in the first line. Oddly, in this case stackdriver seems to select all of the lines.
|
||
Comment 2•7 years ago
|
||
What if we make fast-azure-storage output errors with the rest of the lines attached as an object and then pass that into lib-monitor as extra data when reporting?
|
|
||
Comment 3•7 years ago
|
||
I believe they use https://github.com/GoogleCloudPlatform/fluent-plugin-detect-exceptions for this.
|
|
Assignee | |
Comment 4•7 years ago
|
||
What if we make fast-azure-storage output errors with the rest of the lines attached as an object and then pass that into lib-monitor as extra data when reporting?
In this case, I don't think the extra lines are that useful -- the time is captured elsewhere in the log, and who knows what the requestId correlates to.
Thanks for the link to that library!
|
|
Assignee | |
Comment 5•7 years ago
|
||
|
|
Assignee | |
Comment 6•7 years ago
|
||
|
|
Assignee | |
Comment 7•7 years ago
|
||
Either we haven't had any errors in a week, or this broke error reporting :(
|
|
Assignee | |
Comment 8•7 years ago
|
||
So I can confirm that this works. This is an Azure error which would previously have been reported as a "Time: .." error and now has a one-line stack.
However, this has not appeared in the error reporting view. No errors have been reported at all since April 29. Which is well before this bug was landed.
I deployed https://github.com/taskcluster/taskcluster/compare/f283feaa...eaf924bb at that time. Let's see..
|
|
Assignee | |
Comment 9•7 years ago
|
||
https://github.com/taskcluster/taskcluster/pull/589 is a possible culprit by changing related code, but landed on April 18 and there are lots of errors reported between April 18 and April 29.
We have a nice indicator that error reporting is still working in the "TypeError: gh.apps.getInstallations is not a function" error, which occurs almost constantly. That came to an abrupt stop on April 29.
There is one class of error reported 31 times on May 6 -- it's the "Time: ..." error. But only 31 times, and only on that day, despite comment 6 happening on May 9, three days later. It looks like that came from tc-index (not that SD Errors made that easy to figure out), and the Heroku activity log suggests we didn't deploy that on the 29th.
Here's a message that error-reporting ignored:
{
"insertId": "28dphfg24bo10b",
"jsonPayload": {
"Timestamp": 1557878931464000000,
"serviceContext": {
"version": "590a1812eac2aaaadeff926e65593e65217dc3e7"
},
"Severity": 3,
"Logger": "taskcluster.github.handlers",
"message": "ResourceNotFoundError: The specified resource does not exist.",
"Fields": {
"statusCode": 404,
"message": "The specified resource does not exist.\nRequestId:ba0376da-d002-0111-09b2-0a6053000000\nTime:2019-05-15T00:08:51.4269920Z",
"stack": "ResourceNotFoundError: The specified resource does not exist.\n at /app/node_modules/fast-azure-storage/lib/table.js:401:27\n at tryCallOne (/app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:37:12)\n at /app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:123:15\n at flush (/app/node_modules/asap/raw.js:50:29)\n at process._tickCallback (internal/process/next_tick.js:61:11)",
"module": "fast-azure-storage",
"name": "ResourceNotFoundError",
"payload": "{\"odata.error\":{\"code\":\"ResourceNotFound\",\"message\":{\"lang\":\"en-US\",\"value\":\"The specified resource does not exist.\\nRequestId:ba0376da-d002-0111-09b2-0a6053000000\\nTime:2019-05-15T00:08:51.4269920Z\"}}}",
"v": 1,
"query": {
"timeout": 7
},
"path": "/TaskclusterGithubBuilds(PartitionKey='JuST1xgeSXexX8-kBHyiow',RowKey='taskGroupId')",
"headers": {
"x-ms-client-request-id": "fast-azure-storage",
"accept": "application/json;odata=fullmetadata",
"x-ms-date": "Wed, 15 May 2019 00:08:51 GMT",
"dataserviceversion": "3.0",
"x-ms-version": "2014-02-14"
},
"method": "GET",
"code": "ResourceNotFound",
"retries": 0
},
"Hostname": "b2d1ee78-27b6-46df-8fab-e45813b5d14e",
"Pid": 10,
"Type": "monitor.error",
"EnvVersion": "2.0"
},
"resource": {
"type": "gce_instance",
"labels": {
"instance_id": "heroku",
"zone": "heroku",
"project_id": "heroku-logging"
}
},
"timestamp": "2019-05-15T00:08:51.465046Z",
"severity": "ERROR",
"labels": {
"compute.googleapis.com/resource_name": "4f851adb-cef1-44f4-ac36-4c54682c8e35"
},
"logName": "projects/heroku-logging/logs/github",
"receiveTimestamp": "2019-05-15T00:08:55.403342905Z"
}
Here's one of those 31:
{
"insertId": "1xxgpo6fhsc8w8",
"jsonPayload": {
"Severity": 3,
"Logger": "taskcluster.index.root.api",
"message": "EntityAlreadyExistsError: The specified entity already exists.\nRequestId:ec031246-7002-010b-507f-0438a4000000\nTime:2019-05-07T02:51:11.3903330Z\n at /app/node_modules/fast-azure-storage/lib/table.js:401:27\n at tryCallOne (/app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:37:12)\n at /app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:123:15\n at flush (/app/node_modules/asap/raw.js:50:29)\n at process._tickCallback (internal/process/next_tick.js:61:11)",
"Fields": {
"requestBody": {
"__buf0_data": "e30=",
"PartitionKey": "90bf8f51e36b9cdba2b2f717ed180379b34cba5fb3b4ea5550228fd3d9dce411d10362fd43b15fba60dfd2a0cf4eeb4ef966c8e8064c7095c8749e94c1e15e0b",
"__bufchunks_data": 1,
"expires@odata.type": "Edm.DateTime",
"name": "bn-BD",
"Version": 1,
"taskId@odata.type": "Edm.Guid",
"taskId": "0f979be7-17e0-4edf-b047-19f90207e162",
"rank": 1557186959,
"expires": "2020-05-06T02:30:10.591Z",
"__buf0_data@odata.type": "Edm.Binary",
"namespace": "gecko.v2.mozilla-beta.nightly.revision.fe6ddfaa325f8e9b57b134cd5ff48753726b8aff.firefox-l10n.linux64-opt",
"RowKey": "bn-BD"
},
"path": "/IndexedTasks",
"headers": {
"accept": "application/json;odata=fullmetadata",
"content-length": 560,
"content-type": "application/json",
"x-ms-version": "2014-02-14",
"x-ms-client-request-id": "fast-azure-storage",
"prefer": "return-no-content",
"x-ms-date": "Tue, 07 May 2019 02:50:59 GMT",
"dataserviceversion": "3.0"
},
"method": "insertTask",
"retries": 1,
"code": "EntityAlreadyExists",
"message": "The specified entity already exists.\nRequestId:ec031246-7002-010b-507f-0438a4000000\nTime:2019-05-07T02:51:11.3903330Z",
"statusCode": 409,
"incidentId": "cc4dd5cf-9488-48b9-bc52-fa4a20e2487b",
"stack": "EntityAlreadyExistsError: The specified entity already exists.\nRequestId:ec031246-7002-010b-507f-0438a4000000\nTime:2019-05-07T02:51:11.3903330Z\n at /app/node_modules/fast-azure-storage/lib/table.js:401:27\n at tryCallOne (/app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:37:12)\n at /app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:123:15\n at flush (/app/node_modules/asap/raw.js:50:29)\n at process._tickCallback (internal/process/next_tick.js:61:11)",
"module": "fast-azure-storage",
"payload": {
"expires": {},
"data": {},
"taskId": "D5eb5xfgTt-wRxn5AgfhYg",
"rank": 1557186959
},
"name": "EntityAlreadyExistsError",
"params": {
"namespace": "gecko.v2.mozilla-beta.nightly.revision.fe6ddfaa325f8e9b57b134cd5ff48753726b8aff.firefox-l10n.linux64-opt.bn-BD"
},
"v": 1,
"query": {
"timeout": 7
}
},
"Hostname": "5b67c055-4fff-49c8-adf9-0a2197f760b0",
"Pid": 10,
"Type": "monitor.error",
"EnvVersion": "2.0",
"Timestamp": 1557197471461000000,
"serviceContext": {
"version": "f283feaacb60b06d47c2a24344e857f9a2c7d217",
"service": "index"
}
}
and here's one from the 28th when error reporting was at its normal level of brokenness:
{
"insertId": "1ubq993g49crc79",
"jsonPayload": {
"message": "OperationTimedOutError: Operation could not be completed within the specified time.",
"Fields": {
"stack": "OperationTimedOutError: Operation could not be completed within the specified time.\nRequestId:3d1016aa-7003-0036-176b-fdae60000000\nTime:2019-04-28T02:40:07.1514364Z\n at /app/node_modules/fast-azure-storage/lib/queue.js:321:27\n at tryCallOne (/app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:37:12)\n at /app/node_modules/fast-azure-storage/node_modules/promise/lib/core.js:123:15\n at flush (/app/node_modules/asap/raw.js:50:29)\n at process._tickCallback (internal/process/next_tick.js:61:11)",
"module": "fast-azure-storage",
"payload": {
"workerGroup": "us-west-1",
"workerId": "i-041b0c37ad18eb914",
"tasks": 1
},
"name": "OperationTimedOutError",
"params": {
"workerType": "gecko-t-linux-xlarge",
"provisionerId": "aws-provisioner-v1"
},
"v": 1,
"method": "claimWork",
"retries": 0,
"code": "OperationTimedOut",
"message": "Operation could not be completed within the specified time.\nRequestId:3d1016aa-7003-0036-176b-fdae60000000\nTime:2019-04-28T02:40:07.1514364Z",
"statusCode": 500,
"incidentId": "53962e5d-5df2-472e-91d1-dbd008ac15bd"
},
"Pid": 36,
"Hostname": "4a704c6c-09b3-45a7-b96f-a4118b23028d",
"Type": "monitor.error",
"EnvVersion": "2.0",
"Timestamp": 1556419207201000000,
"serviceContext": {
"version": "07bd0c82a1092a9cbdaed218da08cd7e3e7a00c5",
"service": "queue"
},
"Severity": 3,
"Logger": "taskcluster.queue.root.api"
},
"resource": {
"type": "gce_instance",
"labels": {
"instance_id": "heroku",
"zone": "heroku",
"project_id": "heroku-logging"
}
},
"timestamp": "2019-04-28T02:40:07.201439Z",
"severity": "ERROR",
"labels": {
"compute.googleapis.com/resource_name": "832520a9-1a73-4e57-b797-6b9f336f7807"
},
"logName": "projects/heroku-logging/logs/queue",
"receiveTimestamp": "2019-04-28T02:40:10.399599109Z"
}
|
|
Assignee | |
Comment 10•7 years ago
|
||
https://github.com/taskcluster/taskcluster/pull/589 is a possible culprit by changing related code, but landed on April 18 and there are lots of errors reported between April 18 and April 29.
https://cloud.google.com/error-reporting/docs/formatting-error-messages suggests that the jsonPayload.message property must contain the full stack trace, which that PR would have removed. Queue was deployed with that change on the 18th, and sure enough that's the last error report I see from queue.
So I think the fix is to always include "<first line of message>\n<stack frames>" in jsonPayload.message when there's a stack, and otherwise only include "<first line of message>" in that property, continuing to retain all lines of the message in jsonPayload.Fields.message and the full stack trace in jsonPayload.Fields.stack.
|
|
Assignee | |
Comment 11•7 years ago
|
||
|
|
Assignee | |
Comment 12•7 years ago
|
||
We have an error report!! https://console.cloud.google.com/errors/CI6-sfyJ0eH6dQ?time=PT1H&refresh=auto&project=heroku-logging
Description
•