How to fix Docker container JSON logs from not being formatted correctly?

[65pony]

We are using the latest ta for docker logs, ta-dockerlogs_fileinput. When we look at the data within Splunk, each line of the message is showing up as a different messages. I have attached the sample of the docker containers json.log as well as how they look in the various tools we are looking at; raw data, within Splunk and within the Docker UCP. These are all different visualizations of the same log messages. It looks like a props and transform issue that I hope you guys can help me with.

raw data from /var/lib/docker/containers/*json.log
{"log":"[02:13:03] \u001b[31merror\u001b[39m [core.server.api.services.invoke.proxy.handler] Error: Bad response from service [globalnavbar]\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435148335Z"}
{"log":"    at InvokeError.Error (native)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435153835Z"}
{"log":"    at new InvokeError (/gssp/app/node_modules/remix-common/lib/errors/InvokeError.js:22:89)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435158035Z"}
{"log":"    at /gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:46:31\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435161435Z"}
{"log":"    at process._tickCallback (internal/process/next_tick.js:103:7)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435165035Z"}
{"log":"From previous event:\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435168435Z"}
{"log":"    at /gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:25:75\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435171635Z"}
{"log":"    at tryOnImmediate (timers.js:534:15)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435174835Z"}
{"log":"    at processImmediate [as _immediateCallback] (timers.js:514:5)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435178235Z"}
{"log":"From previous event:\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435182135Z"}
{"log":"    at exports.default (/gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:18:8)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435193035Z"}
{"log":"From previous event:\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435197335Z"}
{"log":"    at exports.default (/gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.handler.js:46:8)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435200735Z"}
{"log":"    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435207735Z"}
{"log":"    at next (/gssp/app/node_modules/express/lib/router/route.js:131:13)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435211835Z"}
{"log":"    at Route.dispatch (/gssp/app/node_modules/express/lib/router/route.js:112:3)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435220635Z"}
{"log":"    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435224135Z"}
{"log":"    at /gssp/app/node_modules/express/lib/router/index.js:277:22\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435227535Z"}
{"log":"    at Function.process_params (/gssp/app/node_modules/express/lib/router/index.js:330:12)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435230635Z"}
{"log":"    at next (/gssp/app/node_modules/express/lib/router/index.js:271:10)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435234135Z"}
{"log":"    at Function.handle (/gssp/app/node_modules/express/lib/router/index.js:176:3)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435241635Z"}
{"log":"    at router (/gssp/app/node_modules/express/lib/router/index.js:46:12)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435245035Z"}
{"log":"    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435248135Z"}
{"log":"    at trim_prefix (/gssp/app/node_modules/express/lib/router/index.js:312:13)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435251335Z"}
{"log":"    at /gssp/app/node_modules/express/lib/router/index.js:280:7\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435254535Z"}
{"log":"    at Function.process_params (/gssp/app/node_modules/express/lib/router/index.js:330:12)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435262535Z"}
{"log":"    at next (/gssp/app/node_modules/express/lib/router/index.js:271:10)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435266035Z"}
{"log":"    at /gssp/app/node_modules/express/lib/router/index.js:618:15\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435269335Z"}
{"log":"    at next (/gssp/app/node_modules/express/lib/router/index.js:256:14)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435272535Z"}
{"log":"    at Function.handle (/gssp/app/node_modules/express/lib/router/index.js:176:3)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435275835Z"}
{"log":"    at router (/gssp/app/node_modules/express/lib/router/index.js:46:12)\r\n","stream":"stdout","time":"2016-11-03T14:13:03.435279035Z"}

In Splunk

As Seen in Docker UCP

[02:13:03] [31merror[39m [core.server.api.services.invoke.proxy.handler] Error: Bad response from service [globalnavbar]
    at InvokeError.Error (native)
    at new InvokeError (/gssp/app/node_modules/remix-common/lib/errors/InvokeError.js:22:89)
    at /gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:46:31
    at process._tickCallback (internal/process/next_tick.js:103:7)
From previous event:
    at /gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:25:75
    at tryOnImmediate (timers.js:534:15)
    at processImmediate [as _immediateCallback] (timers.js:514:5)
From previous event:
    at exports.default (/gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.js:18:8)
From previous event:
    at exports.default (/gssp/app/node_modules/remix-server/lib/api/services/invoke.proxy.handler.js:46:8)
    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)
    at next (/gssp/app/node_modules/express/lib/router/route.js:131:13)
    at Route.dispatch (/gssp/app/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)
    at /gssp/app/node_modules/express/lib/router/index.js:277:22
    at Function.process_params (/gssp/app/node_modules/express/lib/router/index.js:330:12)
    at next (/gssp/app/node_modules/express/lib/router/index.js:271:10)
    at Function.handle (/gssp/app/node_modules/express/lib/router/index.js:176:3)
    at router (/gssp/app/node_modules/express/lib/router/index.js:46:12)
    at Layer.handle [as handle_request] (/gssp/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/gssp/app/node_modules/express/lib/router/index.js:312:13)
    at /gssp/app/node_modules/express/lib/router/index.js:280:7
    at Function.process_params (/gssp/app/node_modules/express/lib/router/index.js:330:12)
    at next (/gssp/app/node_modules/express/lib/router/index.js:271:10)
    at /gssp/app/node_modules/express/lib/router/index.js:618:15
    at next (/gssp/app/node_modules/express/lib/router/index.js:256:14)
    at Function.handle (/gssp/app/node_modules/express/lib/router/index.js:176:3)
    at router (/gssp/app/node_modules/express/lib/router/index.js:46:12)

[aaraneta_splunk]

@65pony - Were you able to test out halr9000's solution? Did it work? If yes, please don't forget to resolve this post by clicking on "Accept". If you still need more help, please provide a comment with some feedback. Thanks!

[halr9000]

if you haven't by now (I know this Q is old), be sure you are running Docker 1.13 so that you can take advantage of the latest JSON and RAW modes in our logging driver as detailed in this blog post. One of these modes (depending on whether you care about embedded JSON) should allow you to take better advantage of the processing pipeline and to be able to handle these events.

If you continue to have issues, let us know.