Habitat: Add option to configure the fields present in Supervisor log output

[tashimi]

Having the option to configure log outputs (similar to what one can do with, say, uWSGI or Apache logs) would be really helpful for controlling noise, i.e. the ability to pick and choose which fields are output and in what order (from Supervisor logs).

As an example of this with another program (uWSGI): http://uwsgi-docs.readthedocs.io/en/latest/LogFormat.html

Something like this could potentially be a big argument in favor of Habitizing stuff, because doing so would then give users "one way" to control logs across N services/programs.

[bixu]

@mspringfeldt, anything you want to add here?

[christophermaier]

Also consider the ability to output JSON-formatted logs here, which was explored in #3750

[christophermaier]

Update: according to @bixu, even just a plain "logs are JSON" option would be good for an initial pass. uWSGI-style config could come later.

[bixu]

That's right. As an example, here's some log data. First, from our systemd journal (what we collect and ship to ELK):
Apr 06 13:37:52 production-api-4 hab[1161]: api_celeryd_events.production(O): {"message": "Received task: smartb.celery.event_tasks.detect_events_task[045339d9-7a82-4028-9cde-4a5490ca23b6] "}

Then, what we see inside Kibana after aggregation:

{
  "_index": "logzioCustomerIndex180406_v2",
  "_type": "journal",
  "_id": "AWKbLYAz9SDreRYhstYH.account-16055",
  "_version": 1,
  "_score": null,
  "_source": {
    "_PID": "1161",
    "_CAP_EFFECTIVE": "3fffffffff",
    "logzio_codec": "json",
    "PRIORITY": "6",
    "@realtime_timestamp": 1523021872490152,
    "type": "journal",
    "_GID": "0",
    "_MACHINE_ID": "a6be1112c1314d259c2bc5820aa3dab2",
    "MESSAGE": "\u001bapi_celeryd_events.production\u001b(\u001bO\u001b): {\"message\": \"Received task: smartb.celery.event_tasks.detect_events_task[045339d9-7a82-4028-9cde-4a5490ca23b6]  \"}",
    "_TRANSPORT": "stdout",
    "_CMDLINE": "/hab/pkgs/core/hab-launcher/7014/20180214015237/bin/hab-launch run --peer 172.31.4.203",
    "SYSLOG_IDENTIFIER": "hab",
    "beat": {
      "version": "5.6.0",
      "name": "journalbeat",
      "hostname": "production-api-4"
    },
    "_SYSTEMD_SLICE": "system.slice",
    "SYSLOG_FACILITY": "3",
    "_UID": "0",
    "_EXE": "/hab/pkgs/core/hab-launcher/7014/20180214015237/bin/hab-launch",
    "timestamp": "2018 ",
    "@metadata": {
      "type": "journal",
      "beat": "journalbeat"
    },
    "_SYSTEMD_CGROUP": "/system.slice/hab-supervisor.service",
    "tags": [
      "production",
      "beats-5015",
      "_logzio_codec_json"
    ],
    "_COMM": "hab-launch",
    "_BOOT_ID": "987adfd89a5648e68fd56970b5b95049",
    "@timestamp": "2018-04-06T13:37:52.490Z",
    "_SYSTEMD_UNIT": "hab-supervisor.service",
    "_HOSTNAME": "production-api-4"
  },
  "fields": {
    "@timestamp": [
      1523021872490
    ]
  },
  "sort": [
    1523021872490
  ]
}

So we think that being able to JSON-format that little bit of Supervisor output (\u001bapi_celeryd_events.production\u001b(\u001bO\u001b):) would be a good start. (Also it looks like somehow we have ANSI color codes bleeding in here...? Have to investigate that some more...)

[bixu]

Ah - it looks like the Terraform Habitat provisioner doesn't turn off color by default when setting up the hab-supervisor systemd service...

[eeyun]

cc @nsdavidson ^

All of these things in mind - I am a huge fan of this feature

[nsdavidson]

Tracking issue for disabling colors in the TF provisioner here: https://github.com/hashicorp/terraform/issues/17799

[christophermaier]

Additional potential feature: be able to separate supervisor-specific logging and service-specific logging into distinct streams, since you may need to aggregate or process them differently.

[bixu]

@christophermaier, here's an example of how this might work:

#!/bin/sh
export HOME={{pkg.svc_data_path}}
cd {{pkg.path}}

exec redis-server {{pkg.svc_config_path}}/redis.config | systemd-cat --identifier='{"habitat_service": "{{pkg.name}}"}' 2>&1

I still need to wire this up to our ELKstack to see if the results are parsable in the way we want (shipping logs via smartb/journalbeat).

[christophermaier]

@bixu Ah, cool... if that works, it might be worth writing up as a wiki post in https://forums.habitat.sh

[bixu]

We’ll do so once we’ve successfully deployed a change like this with good results

On 26. Apr 2018, at 22:23, Christopher Maier [e-mail] wrote:

@bixu Ah, cool... if that works, it might be worth writing up as a wiki post in https://forums.habitat.sh

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[bixu]

@christophermaier, this does indeed seem to work as we wanted, which means (at least for those of us using systemd and VMs) that we don't need the Supervisor itself to transform logs into structured format for us.

[christophermaier]

We've got JSON logging now, as of #5033. I will rename this issue to more clearly capture the configurability aspect, and move it back to the backlog.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. We value your input and contribution. Please leave a comment if this issue still affects you.