search

Financial-Times / splunk-heroku

Support for Heroku log drains packaged as a Splunk app.
https://tech.in.ft.com/tech-topics/logging/splunk/logging-from-heroku
MIT License
2 stars 0 forks source link

Large JSON events are not set to the `heroku:app` source type #56

Closed sjparkinson closed 2 years ago

sjparkinson commented 2 years ago

Search for index=heroku sourcetype=heroku and look for correctly formatted JSON messages (ones that have had the SEDCMD rules applied). These messages should not have heroku as their source type.

The suspicion is the messages are hitting a length limit to that the transform regex is not matching as we'd expect. The regex has been tested in regex101 with these messages to confirm it's should match.

https://github.com/Financial-Times/splunk-heroku/blob/0824fbb1ed02f75226a8efde77c4cb6bc1008ed6/app/default/transforms.conf#L21

Screenshot 2022-09-06 at 13 51 06
sjparkinson commented 2 years ago

Example raw event

Source type is heroku from the HEC token configuration.

1065 <190>1 2022-09-06T11:42:21.414765+00:00 host app web.6 - {"error_message":"No secureSessionToken","error_name":"Error","error_stack":"Error: No secureSessionToken\n    at module.exports (/app/server/middleware/get-session.js:6:25)\n    at module.exports (/app/server/middleware/auth.js:54:25)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at module.exports (/app/server/middleware/add-metric-name.js:10:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at urlencodedParser (/app/node_modules/body-parser/lib/types/urlencoded.js:91:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at jsonParser (/app/node_modules/body-parser/lib/types/json.js:110:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cookieParser (/app/node_modules/cookie-parser/index.js:57:14)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at anonymousMiddleware (/app/node_modules/@financial-times/n-express/src/middleware/anon.js:54:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cache (/app/node_modules/@financial-times/n-express/src/middleware/cache.js:30:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)","event":"AUTHENTICATION_ERROR","originalUrl":"/__topic-tracker/f17eed99-d235-41e7-bb02-7b2adac1c5c4/article/162460f3-5707-4857-9676-70aa1d9df203?source=next-article","level":"error","message":""}

Expected event after TRANSFORMS-source_type is applied

Source type should be heroku:app.

{"error_message":"No secureSessionToken","error_name":"Error","error_stack":"Error: No secureSessionToken\n    at module.exports (/app/server/middleware/get-session.js:6:25)\n    at module.exports (/app/server/middleware/auth.js:54:25)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at module.exports (/app/server/middleware/add-metric-name.js:10:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at urlencodedParser (/app/node_modules/body-parser/lib/types/urlencoded.js:91:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at jsonParser (/app/node_modules/body-parser/lib/types/json.js:110:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cookieParser (/app/node_modules/cookie-parser/index.js:57:14)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at anonymousMiddleware (/app/node_modules/@financial-times/n-express/src/middleware/anon.js:54:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cache (/app/node_modules/@financial-times/n-express/src/middleware/cache.js:30:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)","event":"AUTHENTICATION_ERROR","originalUrl":"/__topic-tracker/f17eed99-d235-41e7-bb02-7b2adac1c5c4/article/162460f3-5707-4857-9676-70aa1d9df203?source=next-article","level":"error","message":""}

Actual event

Source type remains as heroku. But the SEDCMD rules are applied successfully.

{"error_message":"No secureSessionToken","error_name":"Error","error_stack":"Error: No secureSessionToken\n    at module.exports (/app/server/middleware/get-session.js:6:25)\n    at module.exports (/app/server/middleware/auth.js:54:25)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at module.exports (/app/server/middleware/add-metric-name.js:10:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at urlencodedParser (/app/node_modules/body-parser/lib/types/urlencoded.js:91:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at jsonParser (/app/node_modules/body-parser/lib/types/json.js:110:7)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cookieParser (/app/node_modules/cookie-parser/index.js:57:14)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at anonymousMiddleware (/app/node_modules/@financial-times/n-express/src/middleware/anon.js:54:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at cache (/app/node_modules/@financial-times/n-express/src/middleware/cache.js:30:2)\n    at newFn (/app/node_modules/express-async-errors/index.js:16:20)\n    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)\n    at trim_prefix (/app/node_modules/express/lib/router/index.js:328:13)\n    at /app/node_modules/express/lib/router/index.js:286:9\n    at Function.process_params (/app/node_modules/express/lib/router/index.js:346:12)\n    at next (/app/node_modules/express/lib/router/index.js:280:10)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)","event":"AUTHENTICATION_ERROR","originalUrl":"/__topic-tracker/f17eed99-d235-41e7-bb02-7b2adac1c5c4/article/162460f3-5707-4857-9676-70aa1d9df203?source=next-article","level":"error","message":""}
sjparkinson commented 2 years ago

This is due to how Splunk works. The regex in a transform is only provided with a limited number of the first characters of a message, based on the value of the LOOKAHEAD property which defaults to 4,096 characters.

We need to tweak the regex to not match for the end of a JSON message.