Showing posts with label logging. Show all posts
Showing posts with label logging. Show all posts

Sunday, October 26, 2025

Elixir Syslog Logger

Now that Elixir is fully integrated with the Erlang/OTP logger, using custom Elixir logger backends has been deprecated in favor of Erlang/OTP logger handlers.

So if you want improved systemd-journald logging that handles multi-line messages properly and propagates log levels, you can still use the ExSyslogger Elixir logger backend (which I advocated in my 2021 Elixir Systemd Logging blog post) — but the "modern" way is to use an Erlang/OTP logger handler that natively makes libc syslog calls.

Lukas Backström maintains just such a logger handler: syslogger. You can use it to replace the default handler in an Elixir project (that would normally log everything to stdout) with the following steps:

1. Add the syslogger dependency

First, add the syslogger library as a dependency to your mix.exs file. Unfortunately syslogger isn't available as a Hex package, so you have to pull the source from GitHub directly:

# mix.exs defp deps do [ {:syslogger, git: "https://github.com/garazdawi/syslogger.git", ref: "64d3b22"} ] end

2. Override default_handler module

Next, override the module option for the default_handler configuration of Elixir's logger to use syslogger in your config/prod.exs file:

# config/prod.exs config :logger, :default_handler, module: :syslogger

At this point, you've done enough to send all of your logging (in production) through the standard syslog /dev/log socket instead of stdout.

3. Configure syslogger

The main two configuration options of syslogger that you can adjust are the program identifier (aka ident) and facility under which messages will be logged. The defaults are to use the name of your program as the identifier, and user as the facility. You can change the defaults by setting the ident and facility options in your config/prod.exs file:

# config/prod.exs config :syslogger, :ident, ~c"my_app" config :syslogger, :facility, :daemon

4. Remove timestamp formatting

You will probably want to remove the extra timestamp in log messages output by syslogger, since syslog will include the timestamp automatically as part of its structured log data; you can do this by overriding the format option for the Elixir logger's default_formatter to remove the $time token in your config/prod.exs file:

# config/prod.exs config :logger, :default_formatter, format: "$metadata[$level] $message\n", metadata: [:request_id]

5. Remove ex_syslogger

If you were using the ex_syslogger library, remove it as a dependency in your mix.exs file:

# mix.exs defp deps do [ {:ex_syslogger, "~> 1.5"} ] end

And remove the backends option from the root logger configuration in your config/prod.exs file:

# config/prod.exs config :logger, level: :info, backends: [{ExSyslogger, :ex_syslogger}] config :logger, level: :info

And remove the ex_syslogger options from your config/config.exs file:

# config/config.exs config :logger, :ex_syslogger, format: "$time $metadata[$level] $message\n", metadata: [:request_id], ident: "my_app"

Friday, June 11, 2021

Send Journald to CloudWatch Logs with Vector

Timber's Vector log collection tool is a nifty Swiss Army knife for collecting and shipping logs and metrics from one system to another. In particular, I think it's the best tool for shipping structured journald events to CloudWatch Logs.

Here's how to start using Vector to send journald log events to CloudWatch:

Grant Permissions to EC2 Roles

In order to push logs (or metrics) from your EC2 instances to CloudWatch, you first need to grant those EC2 instances some CloudWatch permissions. The permissions you need are basically the same as the AWS CloudWatch Agent needs, so just follow the Create IAM roles and users for use with the CloudWatch agent tutorial to assign the AWS-managed CloudWatchAgentServerPolicy to the IAM roles of the EC2 instances from which you plan on shipping journald logs.

The current version of the CloudWatchAgentServerPolicy looks like this:

{ "Version": "2012-10-17", "Statement": [ { "Effect": "Allow", "Action": [ "cloudwatch:PutMetricData", "ec2:DescribeVolumes", "ec2:DescribeTags", "logs:PutLogEvents", "logs:DescribeLogStreams", "logs:DescribeLogGroups", "logs:CreateLogStream", "logs:CreateLogGroup" ], "Resource": "*" }, { "Effect": "Allow", "Action": [ "ssm:GetParameter" ], "Resource": "arn:aws:ssm:*:*:parameter/AmazonCloudWatch-*" } ] }

With the Vector configuration described below, however, you actually only need to grant the logs:PutLogEvents, logs:DescribeLogStreams, logs:DescribeLogGroups, logs:CreateLogStream, and logs:CreateLogGroup permissions to your EC2 roles.

Install Vector

Installing Vector is easy on Linux. Timber maintains their own deb repo for Vector, so on a Debian-based distro like Ubuntu, you can just update the system's APT package manager with the Vector signing-key and repo, and install the Vector package:

$ wget https://repositories.timber.io/public/vector/gpg.3543DB2D0A2BC4B8.key -O - | sudo apt-key add - $ cat <<EOF | sudo tee /etc/apt/sources.list.d/timber-vector.list deb https://repositories.timber.io/public/vector/deb/ubuntu focal main deb-src https://repositories.timber.io/public/vector/deb/ubuntu focal main EOF $ sudo apt update $ sudo apt install vector

Configure Vector

The default Vector config file, located at /etc/vector/vector.toml, just includes a sample source and sink, so you can replace it entirely with your own config settings. This is the minimum you need to ship journald logs to CloudWatch:

[sources.my_journald_source] type = "journald" [sinks.my_cloudwatch_sink] type = "aws_cloudwatch_logs" inputs = ["my_journald_source"] compression = "gzip" encoding.codec = "json" region = "us-east-1" group_name = "myenv" stream_name = "mysite/myhost"

Replace the CloudWatch region, group_name, and stream_name settings above with whatever's appropriate for your EC2 instances.

Restart Vector

In one terminal screen, watch for errors by tailing Vector's own log entries with the journalctl -u vector -f command, and in another terminal restart Vector with the sudo systemctl restart vector command. If everything works, this is what you'll see in Vector's own logs:

$ journalctl -u vector -f Jun 11 19:54:02 myhost systemd[1]: Started Vector. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.008 INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=trace,rdkafka=info" Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.008 INFO vector::sources::host_metrics: PROCFS_ROOT is unset. Using default '/proc' for procfs root. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.008 INFO vector::sources::host_metrics: SYSFS_ROOT is unset. Using default '/sys' for sysfs root. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.010 INFO vector::app: Loading configs. path=[("/etc/vector/vector.toml", Some(Toml))] Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.060 INFO vector::topology: Running healthchecks. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.060 INFO vector::topology: Starting source. name="journald" Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.061 INFO vector::topology: Starting sink. name="aws_cloudwatch_logs" Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.061 INFO vector: Vector has started. version="0.14.0" arch="x86_64" build_id="5f3a319 2021-06-03" Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.062 INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.063 INFO journald-server: vector::sources::journald: Starting journalctl. Jun 11 19:54:03 myhost vector[686208]: Jun 11 19:54:03.128 INFO vector::sinks::aws_cloudwatch_logs: Skipping healthcheck log group check: `group_name` will be created if missing. Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.430 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs: Sending events. events=4 Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.453 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs::request: Log group provided does not exist; creating a new one. Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.489 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs::request: Group created. name=myenv Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.507 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs::request: Stream created. name=mysite/myhost Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.523 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs::request: Putting logs. token=None Jun 11 19:55:04 myhost vector[686208]: Jun 11 19:55:04.560 INFO sink{component_kind="sink" component_name=aws_cloudwatch_logs component_type=aws_cloudwatch_logs}:request{request_id=0}: vector::sinks::aws_cloudwatch_logs::request: Putting logs was successful. next_token=Some("49610241853835534178700884863462197886393926766970915618")

If something went wrong, Vector will output some error messages (these are especially helpful as you add transformation steps to your basic Vector configuration).

Check Your CloudWatch Logs

Vector will have also shipped some logs to CloudWatch, so check them now. If you use a command-line tool like Saw, you'll see some log events like this:

$ saw watch myenv --expand --prefix mysite [2021-06-11T13:00:27-07:00] (myhost) { "PRIORITY": "6", "SYSLOG_FACILITY": "3", "SYSLOG_IDENTIFIER": "uwsgi", "_BOOT_ID": "6cb87d254d3742728b4fe20e746bcbe6", "_CAP_EFFECTIVE": "0", "_CMDLINE": "/usr/bin/uwsgi /etc/myapp/uwsgi.ini", "_COMM": "uwsgi", "_EXE": "/usr/bin/uwsgi-core", "_GID": "33", "_MACHINE_ID": "ec2aff1204bfae2781faf97e68afb1d4", "_PID": "363", "_SELINUX_CONTEXT": "unconfined\n", "_STREAM_ID": "aa261772c2e74663a7bb122c24b92e64", "_SYSTEMD_CGROUP": "/system.slice/myapp.service", "_SYSTEMD_INVOCATION_ID": "b5e117501bbb43428ab7565659022c20", "_SYSTEMD_SLICE": "system.slice", "_SYSTEMD_UNIT": "myapp.service", "_TRANSPORT": "stdout", "_UID": "33", "__MONOTONIC_TIMESTAMP": "511441719050", "__REALTIME_TIMESTAMP": "1623441627906124", "host": "myhost", "message": "[pid: 363|app: 0|req: 501/501] 203.0.113.2 () {34 vars in 377 bytes} [Fri Jun 11 20:00:27 2021] HEAD / =< generated 0 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 78 bytes (0 switches on core 0)", "source_type": "journald" }

With Saw, use the saw watch command to tail log events as they come in, and use the saw get command to get historical events. For example, this command will print the last 10 minutes of events using the mysite log stream prefix from the myenv log group:

$ saw get myenv --expand --pretty --prefix mysite --start -10m

Filter and Remap Your Logs

With that working, you can tune your Vector configuration to filter out log events you don't care about, and remap certain log fields into a more useful format. Let's add two "transform" steps to our /etc/vector/vector.toml file between the Journald Source and the AWS CloudWatch Logs Sink: a Filter transform, and a Remap transform:

[sources.my_journald_source] type = "journald" [transforms.my_journald_filter] type = "filter" inputs = ["my_journald_source"] condition = ''' (includes(["0", "1", "2", "3", "4"], .PRIORITY) || includes(["systemd", "uwsgi"], .SYSLOG_IDENTIFIER)) ''' [transforms.my_journald_remap] type = "remap" inputs = ["my_journald_filter"] source = ''' .app = .SYSLOG_IDENTIFIER .datetime = to_timestamp(round((to_int(.__REALTIME_TIMESTAMP) ?? 0) / 1000000 ?? 0)) .facility = to_syslog_facility(to_int(.SYSLOG_FACILITY) ?? 0) ?? "" .severity = to_int(.PRIORITY) ?? 0 .level = to_syslog_level(.severity) ?? "" ''' [sinks.my_cloudwatch_sink] type = "aws_cloudwatch_logs" inputs = ["my_journald_filter"] compression = "gzip" encoding.codec = "json" region = "us-east-1" group_name = "myenv" stream_name = "mysite/myhost"

In the above pipeline, the my_journald_source step pipes to the my_journald_transform step, which pipes to the my_journald_transform step, which pipes to the my_cloudwatch_sink step (configured via the inputs setting of each receiving step). The condition VRL expression in the filter step drops entries unless the entry's PRIORITY field is less than 5 (aka "emerg", "alert", "crit", "err", and "warning"), or unless the entry's SYSLOG_IDENTITY field is "systemd" or "uwsgi". And the source VRL program in the remap step adds some additional conveniently-formatted fields (app datetime facility severity and level) to each log entry (the ?? operator in the source coerces "fallible" expressions to a default value when they would otherwise throw an error).

Now if you restart Vector and check your CloudWatch logs, you'll see fewer unimportant entries (those with lower priorities or uninteresting sources that we filtered), plus some additional fields that we added:

$ saw watch myenv --expand --prefix mysite [2021-06-11T13:00:27-07:00] (myhost) { "PRIORITY": "6", "SYSLOG_FACILITY": "3", "SYSLOG_IDENTIFIER": "uwsgi", "_BOOT_ID": "6cb87d254d3742728b4fe20e746bcbe6", "_CAP_EFFECTIVE": "0", "_CMDLINE": "/usr/bin/uwsgi /etc/myapp/uwsgi.ini", "_COMM": "uwsgi", "_EXE": "/usr/bin/uwsgi-core", "_GID": "33", "_MACHINE_ID": "ec2aff1204bfae2781faf97e68afb1d4", "_PID": "363", "_SELINUX_CONTEXT": "unconfined\n", "_STREAM_ID": "aa261772c2e74663a7bb122c24b92e64", "_SYSTEMD_CGROUP": "/system.slice/myapp.service", "_SYSTEMD_INVOCATION_ID": "b5e117501bbb43428ab7565659022c20", "_SYSTEMD_SLICE": "system.slice", "_SYSTEMD_UNIT": "myapp.service", "_TRANSPORT": "stdout", "_UID": "33", "__MONOTONIC_TIMESTAMP": "511441719050", "__REALTIME_TIMESTAMP": "1623441627906124", "app": "uwsgi", "datetime": "2021-06-11T20:00:27Z", "facility": "daemon", "host": "myhost", "level": "info", "message": "[pid: 363|app: 0|req: 501/501] 203.0.113.2 () {34 vars in 377 bytes} [Fri Jun 11 20:00:27 2021] HEAD / =< generated 0 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 78 bytes (0 switches on core 0)", "severity": 6, "source_type": "journald" }

And we can use the new fields we added to further filter our output from Saw, as well as print compact log lines with jq:

$ saw watch myenv --raw --prefix mysite --filter '{ $.severity < 4 || $.app = "uwsgi" }' | jq --unbuffered -r '[.datetime, .level, .host, .app, .message] | join(" ")' 2021-06-11T20:00:27Z info myhost uwsgi [pid: 363|app: 0|req: 501/501] 203.0.113.2 () {34 vars in 377 bytes} [Fri Jun 11 20:00:27 2021] HEAD / =< generated 0 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 78 bytes (0 switches on core 0)

Remove Irrelevant Fields

You can also use Vector's remap filter to remove extraneous fields that you don't want to ship to and store in CloudWatch. You can use the del function to delete specific fields from each event — for example, to skip the journald fields which duplicate the custom fields we added:

source = ''' .app = .SYSLOG_IDENTIFIER .datetime = to_timestamp(round((to_int(.__REALTIME_TIMESTAMP) ?? 0) / 1000000 ?? 0)) .facility = to_syslog_facility(to_int(.SYSLOG_FACILITY) ?? 0) ?? "" .severity = to_int(.PRIORITY) ?? 0 .level = to_syslog_level(.severity) ?? "" del(.PRIORITY) del(.SYSLOG_IDENTIFIER) del(.SYSLOG_FACILITY) '''

Or you could replace the original event entirely with a new object that contains just your desired fields:

source = ''' e = {} e.app = .SYSLOG_IDENTIFIER e.cgroup = ._SYSTEMD_CGROUP e.cmd = ._CMDLINE e.facility = to_int(.SYSLOG_FACILITY) ?? 0 e.gid = to_int(._GID) ?? 0 e.host = .host e.message = .message e.monotime = to_int(.__MONOTONIC_TIMESTAMP) ?? 0 e.pid = to_int(._PID) ?? 0 e.realtime = to_int(.__REALTIME_TIMESTAMP) ?? 0 e.datetime = to_timestamp(round(e.realtime / 1000000 ?? 0)) e.severity = to_int(.PRIORITY) ?? 0 e.level = to_syslog_level(e.severity) ?? "" e.uid = to_int(._UID) ?? 0 . = [e] '''

If you change your Vector pipeline to remap events like the above and restart it, you'll now see log events with only the following fields shipped to CloudWatch:

$ saw watch myenv --expand --prefix mysite [2021-06-11T13:00:27-07:00] (myhost) { "app": "uwsgi", "cgroup": "/system.slice/myapp.service", "cmd": "/usr/bin/uwsgi /etc/myapp/uwsgi.ini", "datetime": "2021-06-11T20:00:27Z", "facility": 3, "gid": 33, "host": "myhost", "level": "info", "message": "[pid: 363|app: 0|req: 501/501] 203.0.113.2 () {34 vars in 377 bytes} [Fri Jun 11 20:00:27 2021] HEAD / =< generated 0 bytes in 0 msecs (HTTP/1.1 200) 2 headers in 78 bytes (0 switches on core 0)", "monotime": 511441719050, "pid": 363, "realtime": 1623441627906124, "severity": 6, "uid": 33 }


Edit 4/23/2022: As of Vector 0.21.1, the rounding shown in the to_timestamp examples is no longer fallible — but the to_timestamp function itself is. So the to_timestamp examples should now look like the following:

e.datetime = to_timestamp(round(e.realtime / 1000000)) ?? now()

Friday, March 26, 2021

Elixir Systemd Logging

If you run an Elixir application as a Linux service with systemd, you'll probably find that logging works pretty well out of the box. By default, Elixir uses the Console logger backend, which sends all log messages to stdout. And with systemd services, by default all stdout messages are sent to journald.

This means you can view your application's logs easily via the journalctl command. For example, you can "tail" your app's logs with a command like this (if the systemd unit for the app was named my_app):

journalctl -u my_app -f

You can also configure systemd to send your app's stdout to a custom log file instead of journald, using the StandardOutput directive. You can add that directive to the [Service] section of a systemd unit file (for example, to log to a custom /var/log/my_app.log):

# /etc/systemd/system/my_app.service [Service] ExecStart=/srv/my_app/bin/my_app start ExecStop=/srv/my_app/bin/my_app stop StandardOutput=append:/var/log/my_app.log

Problems

If you collect and ship your log messages off to a centralized log service (like AWS CloudWatch, Google Cloud Logging, Azure Monitor, Splunk, Sumologic, Elasticsearch, Loggly, Datadog, New Relic, etc), you'll find two problems with this, however:

  1. Multi-line messages are broken up into a separate log entry for each line
  2. Log level/priority is lost

You can add some steps further down your logging pipeline to try to correct this, but the easiest way to fix it is at the source: Replace the default Console logger with the ExSyslogger backend.

(Update for 2025: see my Elixir Syslog Logger blog post for an alternative with a "modern" logger handler instead of a now-deprecated logger backend.)

Here's how you'd do that with a Phoenix web app:

1. Add the ex_syslogger dependency

First, add the ex_syslogger library as a dependency to your mix.exs file:

# mix.exs defp deps do [ {:ex_syslogger, "~> 1.5"} ] end

2. Register the ex_syslogger backend

Update the root config :logger options in your config/prod.exs file to register the ExSyslogger backend under the name :ex_syslogger:

# config/prod.exs # Do not print debug messages in production config :logger, level: :info config :logger, level: :info, backends: [{ExSyslogger, :ex_syslogger}]

Note that the :ex_syslogger name isn't special — you can call it whatever you want. It just has to match the name you use in the next section:

3. Configure the ex_syslogger backend

Now add config :logger, :ex_syslogger options to your config/config.exs file to configure the backend named :ex_syslogger that you registered above. I'd suggest just duplicating the configuration you already have for the default :console backend, plus setting the syslog APP-NAME field to your app's name via the ident option:

# config/config.exs # Configures Elixir's Logger config :logger, :console, format: "$time $metadata[$level] $message\n", metadata: [:request_id] config :logger, :ex_syslogger, format: "$time $metadata[$level] $message\n", metadata: [:request_id], ident: "my_app"

Result

Now when you compile your app with MIX_ENV=prod and run it as a systemd service, journald will automatically handle multi-line messages and log levels/priorities correctly. Furthermore, you can use any generic syslog collector to ship log entries to your log service as soon as they occur — with multi-line messages and log levels intact.

For example, when using the default Console logger, an error message from a Phoenix web app would have been displayed like this by journalctl:

$ journalctl -u my_app -f Mar 26 18:21:10 foo my_app[580361]: 18:21:10.337 request_id=Fm_3dFhPMtEHARkAAALy [info] Sent 500 in 16ms Mar 26 18:21:10 foo my_app[580361]: 18:21:10.345 [error] #PID<0.4149.0> running MyAppWeb.Endpoint (connection #PID<0.4148.0>, stream id 1) terminated Mar 26 18:21:10 foo my_app[580361]: Server: foo.example.com:443 (https) Mar 26 18:21:10 foo my_app[580361]: Request: GET /test/error Mar 26 18:21:10 foo my_app[580361]: ** (exit) an exception was raised: Mar 26 18:21:10 foo my_app[580361]: ** (RuntimeError) test runtime error Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:9: MyAppWeb.TestController.error/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.action/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.phoenix_controller_pipeline/2 Mar 26 18:21:10 foo my_app[580361]: (phoenix 1.5.8) lib/phoenix/router.ex:352: Phoenix.Router.__call__/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.plug_builder_call/2 Mar 26 18:21:10 foo my_app[580361]: (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.call/2 Mar 26 18:21:10 foo my_app[580361]: (phoenix 1.5.8) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4 Mar 26 18:21:10 foo my_app[580361]: (cowboy 2.8.0) /srv/my_app/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2

But with ExSyslogger in place, you'll now see this (where the full error message is captured as a single log entry, and is recognized as an error-level message):

$ journalctl -u my_app -f Mar 26 18:21:10 foo my_app[580361]: 18:21:10.337 request_id=Fm_3dFhPMtEHARkAAALy [info] Sent 500 in 16ms Mar 26 18:21:10 foo my_app[580361]: 18:21:10.345 [error] #PID<0.4149.0> running MyAppWeb.Endpoint (connection #PID<0.4148.0>, stream id 1) terminated Server: foo.example.com:443 (https) Request: GET /test/error ** (exit) an exception was raised: ** (RuntimeError) test runtime error (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:9: MyAppWeb.TestController.error/2 (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.action/2 (my_app 0.1.0) lib/my_app_web/controllers/test_controller.ex:1: MyAppWeb.TestController.phoenix_controller_pipeline/2 (phoenix 1.5.8) lib/phoenix/router.ex:352: Phoenix.Router.__call__/2 (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.plug_builder_call/2 (my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.call/2 (phoenix 1.5.8) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4 (cowboy 2.8.0) /srv/my_app/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2

And as a side note, you can use journalctl to view just error-level messages and above via the --priority=err flag (-p3 for short):

journalctl -u my_app -p3

Saturday, January 16, 2016

Filtering Apache Logs by HTTP Status Code

Apparently there was once a Stack Overflow question of the same name, but was deleted. So when I wanted to add a log file just for redirects to an apache httpd server, I had to dig a little through the mod_log_config and expressions documentation.

Starting in version 2.4, apache supports an expr argument to the CustomLog directive to specify an expression that must evaluate to true in order for the request to be logged to the custom log file. So to capture only redirects (responses with a status code in the 300s) for GET requests, I set up the following directive:

CustomLog /var/log/apache2/redirect.log redirect "expr=%{REQUEST_STATUS} -ge 300 && %{REQUEST_STATUS} -lt 400 && %{REQUEST_METHOD} == 'GET'"

The second argument to the directive — redirect — is just the name of the custom log format I defined. It's not a special keyword or anything — it could have been foo or bar or whatever. This is the format I ended up using, capturing the host (%V:%p) and path (%r) requested, the location (%{Location}o) to which the server redirected the request, and the referrer (%{Referer}i) to the original request:

LogFormat "%V:%p %a %t \"%r\" %>s Location: %{Location}o Referer: %{Referer}i" redirect

Thursday, January 5, 2012

Log4j + Jetty 6 + Fedora

Since this is the second time I've had to setup a (Grails) app that uses Log4j with the version of Jetty 6 that comes with Fedora (specifically Fedora 14), I figured I'd document how I had to change the jetty configuration to get the app working right:

Add jsp 2.1 to jetty's lib

Download the latest Jetty 6 release (directly from the Codehaus), and copy its lib/jsp-2.1 directory into the /usr/share/jetty/lib directory you get with Fedora (so that you have a new /usr/share/jetty/lib/jsp-2.1 directory to go along with the existing /usr/share/jetty/lib/jsp-2.0 directory). This should solve your SLF4J problems.

Remove commons-logging.jar from jetty's classpath

The Fedora jetty daemon ultimately runs the /usr/bin/djetty script to start jetty. Edit it to remove the Commons Logging jar from the classpath, and to allow additional java options:

#!/bin/bash if [ -z "$JAVA_OPTIONS" ] then export JAVA_OPTIONS="-Xmx1500m -XX:MaxPermSize=500m" fi if [ -z "$JETTY_CLASSPATH" ] then export JETTY_CLASSPATH="" fi if [ -z "$JETTY_PID" ] then export JETTY_PID=/dev/null fi if [ -z "$JETTY_PORT" ] then export JETTY_PORT=8088 fi export JETTY_HOME=/usr/share/jetty if [ -z "$JETTY_HOME" ] then JETTY_HOME_1=`dirname "$0"` JETTY_HOME_1=`dirname "$JETTY_HOME_1"` JETTY_HOME=${JETTY_HOME_1} fi cd $JETTY_HOME #exec /usr/bin/java -Djetty.class.path=/usr/share/java/commons-logging.jar -Djetty.port=$JETTY_PORT -jar start.jar etc/jetty-logging.xml etc/jetty.xml 2>/dev/null & exec /usr/bin/java -Djetty.class.path="$JETTY_CLASSPATH" -Djetty.port=$JETTY_PORT $JAVA_OPTIONS -jar start.jar etc/jetty-logging.xml etc/jetty.xml 2>/dev/null & echo $! >$JETTY_PID

Now grails' Log4j configuration should take effect.

Remove jetty's javamail.jar

Since the grails apps I've deployed included javamail jars in their own war, I get rid of the /usr/share/jetty/lib/naming/[javamail].jar (symlink) — otherwise sending mail via SMTP just fails silently.

Remove jetty's sample apps

Delete the sample apps in /usr/share/jetty/contexts and /usr/share/jetty/webapps. There's no reason to keep them, and I usually want my apps to use the root context path in their place anyway.