CDNs are great, but they can be a bit of a black box. What if you want to see your CDN traffic broken down by customer? The CDN has that information, but how can we get it out?

Fastly’s CDN hosts our customer’s configuration data so that it is available even if Prefab’s API were to be unavailable. In order to understand our CDN traffic broken down by customer, we set out to use Fastly’s logging product to stream data back to us containing information from our API response but hit a bump in understanding the varnish/Fastly object model.

First Problem: Customer Identification​

The default Fastly Log format doesn’t contain a lot of data. To make downstream computation more straightforward, we set out to add a couple of headers to our API’s configuration responses that would identify the API key used to request the configuration. Those are the prefab-key-id and prefab-env-id.

Second Problem: Getting New Headers Back In Fastly Logs​

First, I thought it would be as easy as adding something like “prefab_env_key_id”: %{beresp.http.Prefab-EnvId}V" to the JSON log format to get the new headers shipped our way, but I was confronted with an error message indicating the vcl_log method didn’t have access to that variable. I asked a question in the Fastly Developers community and got a helpful answer.

Varnish All The Way Down​

Fastly is a great user experience wrapped around the Varnish HTTP Cache, which shows in its references to VCL (Varnish Control Language) snippets and callbacks like vcl_fetch, vcl_deliver, and vcl_log. Each of those callbacks (subroutines) has access to different objects, so the trick is to use those subroutines to copy data from the original (origin) response (known as beresp) in varnish to the cache object resp so that future invocations of vcl_log have access to that.

In Fastly Configuration, Content → Headers let us do this without writing any VCL.

Now that the header Prefab-EnvId is set on the cached object, we can refer to that using resp.http.Prefab-EnvId in the JSON logging format like this

"pf_env_id": "%{json.escape(resp.http.Prefab-EnvId)}V"

After we spent months with all of our Datadog alerts for both staging and production routed to a single slack #alerts channel, we all got tired of looking in that room with urgency to see something happening in staging again. The team asked me to figure out how to create environment-specific alert channels, so here’s what I did.

The Documentation​

The slack integration document includes a mention of using message template variables interpolation to dynamically create @-mentions

Best practices for tagging your infrastructure and applications is a long read on the virtues of adding tags (like team ownership) to infrastructure so those tags can be used in alerts.

TL;DR​

Once you’ve set up a monitor with a Slack alert, you’ll see something like this in the message: @slack-Prefab_Internal-alerts. That’s a hyphen delimited integration name, integration install name, and then the channel.

To target specific environments by the env tag that’s usually available, edit the monitor’s message like this @slack-Prefab_Internal-alerts-{{env.name}}. The drop-down box below the message won’t be helpful, but this works.

Then setup a slack channel like #alerts-production.

You may also want to specify the “Multi Alert” aggregation options we chose.

In Hands-On LSP Tutorial: Building a Custom Auto-Complete, we built a language server to provide our text editors with GitHub Issue and PR completion.

import fetch from "node-fetch";
import {
  createConnection,
  InitializeResult,
  TextDocumentSyncKind,
  TextDocuments,
} from "vscode-languageserver/node";
import { TextDocument } from "vscode-languageserver-textdocument";

const connection = createConnection();

const documents: TextDocuments<TextDocument> = new TextDocuments(TextDocument);

type Edge = {
  node: {
    title: string;
    number: number;
    url: string;
    body: string;
  };
};

type Response = {
  data: { search: { edges: Edge[] } };
};

// Replace with your real GitHub access token
const accessToken = "YOUR_GITHUB_ACCESS_TOKEN";

const searchScope = "repo:facebook/docusaurus";

const search = async (input: string): Promise<Response> => {
  const query = `
  {
    search(query: "${searchScope} ${input}", type: ISSUE, first: 10) {
      edges {
        node {
          ... on PullRequest {
            title
            number
            body
            url
          }
          ... on Issue {
            title
            number
            body
            url
          }
        }
      }
    }
  }
`;

  const response = await fetch("https://api.github.com/graphql", {
    method: "POST",
    body: JSON.stringify({ query }),
    headers: {
      Authorization: `Bearer ${accessToken}`,
    },
  });

  if (!response.ok) {
    const error = {
      status: response.status,
      statusText: response.statusText,
      body: await response.json(),
    };

    connection.console.error(
      `Error fetching from GitHub: ${JSON.stringify(error)}`,
    );
  }

  return await response.json();
};

connection.onInitialize(() => {
  const result: InitializeResult = {
    capabilities: {
      textDocumentSync: TextDocumentSyncKind.Incremental,
      // Tell the client that the server supports code completion
      completionProvider: {
        // We want to listen for the "#" character to trigger our completions
        triggerCharacters: ["#"],
      },
    },
  };

  return result;
});

connection.onCompletion(async (params) => {
  const doc = documents.get(params.textDocument.uri);

  if (!doc) {
    return null;
  }

  const line = doc.getText().split("\n")[params.position.line];

  // return early if we don't see our trigger character
  if (!line.includes("#")) {
    return null;
  }

  const input = line.slice(line.lastIndexOf("#") + 1);

  const json = await search(input);

  const items = json.data.search.edges.map((edge) => {
    return {
      label: `#${edge.node.number}: ${edge.node.title}`,
      detail: `${edge.node.title}\n\n${edge.node.body}`,
      textEdit: {
        range: {
          start: {
            line: params.position.line,
            character: line.lastIndexOf("#"),
          },
          end: {
            line: params.position.line,
            character: params.position.character,
          },
        },
        newText: `${edge.node.url}`,
      },
    };
  });

  return {
    isIncomplete: true,
    items,
  };
});

// Make the text document manager listen on the connection
// for open, change and close text document events
documents.listen(connection);

// Listen on the connection
connection.listen();

It works, but searchScope (e.g., repo:facebook/docusaurus) and our GitHub access token are hard-coded. That's fine for local development, but to get this language server ready to share, we should make those configurable.

Approach​

1. We'll update server.ts to use editor-provided config instead of hard-coded values.
2. We'll update our editor setup to provide config to the server.

Updating our server to use config​

First, we remove previous assignments of accessToken and searchScope.

- // Replace with your real GitHub access token
- const accessToken = "YOUR_GITHUB_ACCESS_TOKEN";
-
- const searchScope = "repo:facebook/docusaurus";

Instead, we specify the shape of our configuration, a default number of max results, and default our config to an empty object.

interface Config {
  githubAccessToken?: string;
  searchScope?: string;
  maxResults?: number;
}

const DEFAULT_MAX_RESULTS = 10;

let config: Config = {};

Next, we change our search query to the searchScope and maxResults from our settings.

- const search = async (input: string): Promise<Response> => {
-   const query = `
-   {
-     search(query: "${searchScope} ${input}", type: ISSUE, first: 10) {

const search = async (input: string): Promise<Response> => {
  const query = `
  {
    search(query: "${config.searchScope} ${input}", type: ISSUE, first: ${
    config.maxResults ?? DEFAULT_MAX_RESULTS
  }) {

We use the token from our config.

- Authorization: `Bearer ${accessToken}`,

Authorization: `Bearer ${config.githubAccessToken}`,

We'll add a getConfig function to get the current config from the editor. We look up our configuration by a prefix we specify (here, myLSP).

const getConfig = async () => {
  config = await connection.workspace.getConfiguration("myLSP");
};

Finally, we call getConfig in our onCompletion function and we return early with an error if we're missing any required fields.

connection.onCompletion(async (params) => {
  await getConfig();

  if (!config.githubAccessToken || !config.searchScope) {
    connection.console.error("Both githubAccessToken and searchScope required");
    return;
  }
  // ...

That's all we needed to change for our server.

import fetch from "node-fetch";
import {
  createConnection,
  InitializeResult,
  TextDocumentSyncKind,
  TextDocuments,
} from "vscode-languageserver/node";
import { TextDocument } from "vscode-languageserver-textdocument";

const connection = createConnection();

const documents: TextDocuments<TextDocument> = new TextDocuments(TextDocument);

type Edge = {
  node: {
    title: string;
    number: number;
    url: string;
    body: string;
  };
};

type Response = {
  data: { search: { edges: Edge[] } };
};

interface Config {
  githubAccessToken?: string;
  searchScope?: string;
  maxResults?: number;
}

const DEFAULT_MAX_RESULTS = 10;

let config: Config = {};

const search = async (input: string): Promise<Response> => {
  const query = `
  {
    search(query: "${config.searchScope} ${input}", type: ISSUE, first: ${
      config.maxResults ?? DEFAULT_MAX_RESULTS
    }) {
      edges {
        node {
          ... on PullRequest {
            title
            number
            body
            url
          }
          ... on Issue {
            title
            number
            body
            url
          }
        }
      }
    }
  }
`;

  const response = await fetch("https://api.github.com/graphql", {
    method: "POST",
    body: JSON.stringify({ query }),
    headers: {
      Authorization: `Bearer ${config.githubAccessToken}`,
    },
  });

  if (!response.ok) {
    const error = {
      status: response.status,
      statusText: response.statusText,
      body: await response.json(),
    };

    connection.console.error(
      `Error fetching from GitHub: ${JSON.stringify(error)}`,
    );
  }

  return await response.json();
};

const getConfig = async () => {
  config = await connection.workspace.getConfiguration("myLSP");
};

connection.onInitialize(() => {
  const result: InitializeResult = {
    capabilities: {
      textDocumentSync: TextDocumentSyncKind.Incremental,
      // Tell the client that the server supports code completion
      completionProvider: {
        // We want to listen for the "#" character to trigger our completions
        triggerCharacters: ["#"],
      },
    },
  };

  return result;
});

connection.onCompletion(async (params) => {
  await getConfig();

  if (!config.githubAccessToken || !config.searchScope) {
    connection.console.error("Both githubAccessToken and searchScope required");
    return;
  }

  const doc = documents.get(params.textDocument.uri);

  if (!doc) {
    return null;
  }

  const line = doc.getText().split("\n")[params.position.line];

  // return early if we don't see our trigger character
  if (!line.includes("#")) {
    return null;
  }

  const input = line.slice(line.lastIndexOf("#") + 1);

  const json = await search(input);

  const items = json.data.search.edges.map((edge) => {
    return {
      label: `#${edge.node.number}: ${edge.node.title}`,
      detail: `${edge.node.title}\n\n${edge.node.body}`,
      textEdit: {
        range: {
          start: {
            line: params.position.line,
            character: line.lastIndexOf("#"),
          },
          end: {
            line: params.position.line,
            character: params.position.character,
          },
        },
        newText: `${edge.node.url}`,
      },
    };
  });

  return {
    isIncomplete: true,
    items,
  };
});

// Make the text document manager listen on the connection
// for open, change and close text document events
documents.listen(connection);

// Listen on the connection
connection.listen();

Providing config from the editor​

As in the previous post, I will cover VS Code and Neovim here.

How to configure your server with VS Code​

VS Code extensions specify configuration via the root package.json. Replace your contributes block with the following:

"contributes": {
  "configuration": {
    "title": "My Extension Name",
    "properties": {
      "myLSP.githubAccessToken": {
        "type": "string",
        "default": "",
        "description": "Your GitHub access token"
      },
      "myLSP.searchScope": {
        "type": "string",
        "default": "repo:facebook/docusaurus",
        "description": "Search scope for GitHub PRs/Issues"
      },
      "myLSP.maxResults": {
        "type": "number",
        "default": 10,
        "description": "Max number of completion suggestions"
      }
    }
  }
},

Note that the myLSP prefix on the properties matches the string we use in our getConfig function.

Once you've repackaged and reinstalled your extension, you can modify the settings by pressing ctrl+shift+p (cmd+shift+p on Mac) and typing "Open Settings UI"

Once in the Settings UI, search for myLSP to modify your settings.

Changes take effect immediately because we pull the settings in our server as needed.

How to configure your server with Neovim​

For Neovim, we modify our vim.lsp.start invocation to add a settings table to our configuration.

vim.lsp.start {
    name = "test-ls",
    --- ...
    settings = {
        myLSP = {
            githubAccessToken = os.getenv("GITHUB_ACCESS_TOKEN"),
            searchScope = "owner:github",
            maxResults = 15,
        }
    },
}

Since we only provide these settings in our vim.lsp.start, you'll need to restart your editor for changes to take effect.

What's next?​

Next, we will look at distributing our language server to make it trivial for our coworkers and friends to install and use in their editors.

If you'd like to be notified when I publish more LSP content, sign up for my newsletter.

What we'll build in this tutorial​

Today, we'll build out completion for linking to GitHub issues and PRs.

Developers can use this completion to reference issues and PRs from their code comments and commit messages.

What is a Language Server?​

Language servers let you meet developers where they are: their editor. They give you the power of in-editor tooling without rebuilding your tools for each editor you want to support. They can implement features like completion, go-to-definition, code actions, and more.

The Language Server Protocol (LSP) specifies how a language server should interface with an editor.

Approach​

1. We'll build a language server prototype with hard-coded completion choices.
2. We'll wire this to our editor and test it out.
3. We'll replace the hard-coded choices with dynamic content from GitHub's API.

Prototyping our Language Server​

We'll build this demo in Typescript.

We install a few dependencies to handle the language server implementation details. We'll also install node-fetch to help us make API requests.

npm install vscode-languageserver vscode-languageserver-textdocument vscode-languageclient node-fetch@2
npm install --save-dev @types/vscode @types/node-fetch

(Don't let the vscode bits confuse you. While Microsoft publishes these packages, your language server will be editor-agnostic.)

Now, we can start writing our code. We'll start with distilled boilerplate code borrowed from the Visual Studio Code Language Server Extension Guide.

import {
  createConnection,
  InitializeResult,
  TextDocumentSyncKind,
  TextDocuments,
} from "vscode-languageserver/node";
import { TextDocument } from "vscode-languageserver-textdocument";

const connection = createConnection();

const documents: TextDocuments<TextDocument> = new TextDocuments(TextDocument);

connection.onInitialize(() => {
  const result: InitializeResult = {
    capabilities: {
      textDocumentSync: TextDocumentSyncKind.Incremental,
      // Tell the client that the server supports code completion
      completionProvider: {
        // We want to listen for the "#" character to trigger our completions
        triggerCharacters: ["#"],
      },
    },
  };

  return result;
});

// Make the text document manager listen on the connection
// for open, change and close text document events
documents.listen(connection);

// Listen on the connection
connection.listen();

After our imports, we set up a connection and some documents. The connection handles the communication between the editor (the client) and our code (the server). documents is a store of open files in our editor. documents stays in sync when files open, close, and change.

When the editor starts our server, onInitialize is fired. The editor sends some params describing what it can do (and what it wants our server to do), but we're not using those here, so we'll omit them. We reply with a list of things we can do (primarily, we offer completions triggered by #).

We tell documents to listen on the connection and the connection to listen for communication from the editor.

Our server could now run hosted by the editor (more on that later), but it doesn't do anything useful yet.

Let's add the initial hard-coded completion after our onInitialize.

connection.onCompletion(() => {
  return [
    {
      label: "Cannot set properties of undefined (setting 'minItems')",
      data: "https://github.com/facebook/docusaurus/issues/9271",
    },
    {
      label: "docs: fix typo in docs-introduction",
      data: "https://github.com/facebook/docusaurus/pull/9267",
    },
    {
      label: "Upgrade notification command does not copy properly",
      data: "https://github.com/facebook/docusaurus/issues/9239",
    },
  ];
});

Now, we're ready to test this out.

Wiring this up to our Editor/IDE​

While the LSP standardizes how to implement Language Servers and how they talk to editors, there's no good standard for making your editor aware of a language server so that it is ready to be used. For this post, I'll cover VS Code and Neovim.

How to connect your Language Server to VS Code​

You connect a language server to VS Code by creating a thin extension layer. To make things as easy as possible for you, I've published a Minimum Viable VS Code Language Server Extension. Follow the directions in that repo and replace the entire contents of server/src/server.ts with the code we're writing in this post.

After following those directions, we'll also need to install node-fetch for the server since the node version packaged with VS Code is too old to include native fetch support.

cd server && npm install node-fetch@2 && npm install --save-dev @types/node-fetch && cd -

Now, you should be able to test your extension with the steps mentioned here. You should be able to open a new file, type #, and then see something like this:

How to connect your Language Server to Neovim​

For Neovim, you pass some configuration to vim.lsp.start. For testing, I've put the following in ~/.config/nvim/after/ftplugin/ruby.lua. Note that this location means it only runs in ruby files. Feel free to start the server elsewhere.

local capabilities = vim.lsp.protocol.make_client_capabilities()

vim.lsp.start {
    name = "test-ls",
    cmd = {
        "npx", "ts-node",
        "/Users/ship/src/lsp-example-completion/server.ts",
        "--stdio"
    },
    capabilities = capabilities
}

I'm using npx ts-node to run my server.ts without an intermediate build step, but you can use whatever approach you prefer.

You should be able to open a new file, type #, and then see something like this:

If you encounter any trouble, check the output of :LspLog

Dynamic Completions​

GitHub provides a GraphQL API. Get a GitHub access token and have it handy. It appears a classic token with "repo" permissions is required to get the search query to work correctly (at the time of writing).

Here's a query to search the Docusaurus repo for issues and PRs that include the word "bug.”

{
  search(query: "repo:facebook/docusaurus bug", type: ISSUE, first: 10) {
    edges {
      node {
        ... on PullRequest {
          title
          number
          body
          url
        }
        ... on Issue {
          title
          number
          body
          url
        }
      }
    }
  }
}

We could replace repo:facebook/docusaurus with owner:facebook to scope search every repo owned by Facebook (that we have access to).

You can replace the searchScope with your organization or repo name when applying the changes below. Be sure to swap out the placeholder YOUR_GITHUB_ACCESS_TOKEN with your token. In a future post, we'll cover language server configuration to pass in our search scope and access token.

import fetch from "node-fetch";

type Edge = {
  node: {
    title: string;
    number: number;
    url: string;
    body: string;
  };
};

type Response = {
  data: { search: { edges: Edge[] } };
};

// Replace with your real GitHub access token
const accessToken = "YOUR_GITHUB_ACCESS_TOKEN";

const searchScope = "repo:facebook/docusaurus";

const search = async (input: string): Promise<Response> => {
  const query = `
  {
    search(query: "${searchScope} ${input}", type: ISSUE, first: 10) {
      edges {
        node {
          ... on PullRequest {
            title
            number
            body
            url
          }
          ... on Issue {
            title
            number
            body
            url
          }
        }
      }
    }
  }
`;

  const response = await fetch("https://api.github.com/graphql", {
    method: "POST",
    body: JSON.stringify({ query }),
    headers: {
      Authorization: `Bearer ${accessToken}`,
    },
  });

  if (!response.ok) {
    const error = {
      status: response.status,
      statusText: response.statusText,
      body: await response.json(),
    };

    connection.console.error(
      `Error fetching from GitHub: ${JSON.stringify(error)}`,
    );
  }

  return await response.json();
};

// ...

connection.onCompletion(async () => {
  const input = "bug";

  const json = await search(input);

  const items = json.data.search.edges.map((edge) => {
    return {
      label: `#${edge.node.number}: ${edge.node.title}`,
      detail: `${edge.node.title}\n\n${edge.node.body}`,
      insertText: edge.node.url,
    };
  });

  return {
    isIncomplete: true,
    items,
  };
});

Note the isIncomplete: true here. This tells the editor that the list we're returning isn't exhaustive and might change over time.

Our language server works!

But it uses our hard-coded search string "bug" instead of completing based on our input. Let's fix that.

connection.onCompletion takes a CompletionParams argument that looks something like this:

{
  "textDocument":{"uri":"file:///private/tmp/example_file.rb"},
  "context":{"triggerKind":3},
  "position":{"line":2,"character":11}
}

With this information and the documents we initialized earlier, we have everything we need to understand what the user was typing.

connection.onCompletion(async (params) => {
  const doc = documents.get(params.textDocument.uri);

  if (!doc) {
    return null;
  }

  const line = doc.getText().split("\n")[params.position.line];

  // return early if we don't see our trigger character
  if (!line.includes("#")) {
    return null;
  }

  const input = line.slice(line.lastIndexOf("#") + 1);

// ...

After selecting our completion choice, you’ll notice that the # character hangs around. How do we prevent this? And why do we need a trigger character anyway?

If we didn't have a trigger character, this completion would trigger constantly as we type any code. That's wasteful for API requests and means we're doing unnecessary work -- we only want to show issues and PRs in very specific scenarios. So, the behavior should be opt-in, and a trigger character is beneficial.

To prevent the # from hanging around, we can replace our naive insertText with a TextEdit. TextEdits allow you to specify a range in the document to replace with new text. We'll modify our completion item formatting function:

const items = json.data.search.edges.map((edge) => {
  return {
    label: `#${edge.node.number}: ${edge.node.title}`,
    detail: `${edge.node.title}\n\n${edge.node.body}`,
    textEdit: {
      range: {
        start: {
          line: params.position.line,
          character: line.lastIndexOf("#"),
        },
        end: {
          line: params.position.line,
          character: params.position.character,
        },
      },
      newText: `${edge.node.url}`,
    },
  };
});
// ...

With this change, we overwrite the # so that only the new content remains.

import fetch from "node-fetch";
import {
  createConnection,
  InitializeResult,
  TextDocumentSyncKind,
  TextDocuments,
} from "vscode-languageserver/node";
import { TextDocument } from "vscode-languageserver-textdocument";

const connection = createConnection();

const documents: TextDocuments<TextDocument> = new TextDocuments(TextDocument);

type Edge = {
  node: {
    title: string;
    number: number;
    url: string;
    body: string;
  };
};

type Response = {
  data: { search: { edges: Edge[] } };
};

// Replace with your real GitHub access token
const accessToken = "YOUR_GITHUB_ACCESS_TOKEN";

const searchScope = "repo:facebook/docusaurus";

const search = async (input: string): Promise<Response> => {
  const query = `
  {
    search(query: "${searchScope} ${input}", type: ISSUE, first: 10) {
      edges {
        node {
          ... on PullRequest {
            title
            number
            body
            url
          }
          ... on Issue {
            title
            number
            body
            url
          }
        }
      }
    }
  }
`;

  const response = await fetch("https://api.github.com/graphql", {
    method: "POST",
    body: JSON.stringify({ query }),
    headers: {
      Authorization: `Bearer ${accessToken}`,
    },
  });

  if (!response.ok) {
    const error = {
      status: response.status,
      statusText: response.statusText,
      body: await response.json(),
    };

    connection.console.error(
      `Error fetching from GitHub: ${JSON.stringify(error)}`,
    );
  }

  return await response.json();
};

connection.onInitialize(() => {
  const result: InitializeResult = {
    capabilities: {
      textDocumentSync: TextDocumentSyncKind.Incremental,
      // Tell the client that the server supports code completion
      completionProvider: {
        // We want to listen for the "#" character to trigger our completions
        triggerCharacters: ["#"],
      },
    },
  };

  return result;
});

connection.onCompletion(async (params) => {
  const doc = documents.get(params.textDocument.uri);

  if (!doc) {
    return null;
  }

  const line = doc.getText().split("\n")[params.position.line];

  // return early if we don't see our trigger character
  if (!line.includes("#")) {
    return null;
  }

  const input = line.slice(line.lastIndexOf("#") + 1);

  const json = await search(input);

  const items = json.data.search.edges.map((edge) => {
    return {
      label: `#${edge.node.number}: ${edge.node.title}`,
      detail: `${edge.node.title}\n\n${edge.node.body}`,
      textEdit: {
        range: {
          start: {
            line: params.position.line,
            character: line.lastIndexOf("#"),
          },
          end: {
            line: params.position.line,
            character: params.position.character,
          },
        },
        newText: `${edge.node.url}`,
      },
    };
  });

  return {
    isIncomplete: true,
    items,
  };
});

// Make the text document manager listen on the connection
// for open, change and close text document events
documents.listen(connection);

// Listen on the connection
connection.listen();

We've only scratched the surface of what language servers can do. There's still plenty of the LSP left to explore.

Read the next article Hands-On LSP Tutorial: Configuration.

If you'd like to be notified when I publish more LSP content, sign up for my newsletter.

What is Tagged Logging?​

Should you be using it? What libraries support it? Is it the same as structured logging?

Let's start with an example. Here's ActiveSupport::TaggedLogging in action.

class Permissions
  def get(user)
    logger.tagged("Auth API") do
      uri = URI("https://auth.example.com/permissions/?user=#{user}")

      logger.info { "Fetching #{uri}" }
      permissions = Permissions.parse(Net::HTTP.get(uri))
      logger.info { "Got permissions #{permissions.to_s}" }
    end
  end
end

# Log Output
#[Auth API] Fetching https://auth.example.com/permissions/?user=bob
#[Auth API] Got permissions admin, writer, reader

An example from Justin Weiss shows us how we might do this for users:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

# Log Output
#[user-123] Finding people...
#[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
#[user-123] Found 0 people!

What's Good About Tagged Logging​

Good Readability / Grep-ability​

It's nice that the log lines for multiple parts of a request have the same tag. That's going to be helpful with ctrl-f locally or grep in production.

It's DRY (Don't Repeat Yourself)​

We put the user.id in one place, and it is now in all the log output. We could even put that in an around_action and have it in all logging for our request.

What's Not as Good​

Poor Machine Readability​

logger.tagged "user-#{user.id}" do
  logger.tagged team.name do
    logger.info "hello"
  end
end

# The plain text version of the log reads nicely
#INFO [user-1] [The Best Team] hello

# But the JSON Log isn't ideal
#{severity: INFO, message: "hello", tags: ["user-123", "The Best Team"]}

Almost every log aggregator will support JSON logging and user-123 won't be as easy to search as {user: 123}. With the structured format you're going to be able to display and search the column user for 123. Additionally, the team name is just floating there without a key. This post Structured logging in Rails lays out the problem well. Does your logging aggregator want:

[2018-05-13T17:51:08.772542] [INFO] [127.0.0.1] [2892] Customer registration error - SSN already exists.

Or

{
  "timestamp": "2018-05-13T17:51:08.772542",
  "source": "127.0.0.1",
  "msg": "SSN already exists.",
  "level": "INFO",
  "user_id": 2892,
  "error_type": "customer_registration"
}

The answer is almost assuredly the latter.

The gem json_tagged_logger gets in the fight here. It takes the same tagging behavior and puts them in a tags key.

Rails.logger.tagged("TAG") do
    Rails.logger.tagged("NESTED").info("nested tagged log message")
end

# Log Output
{
    "level": "INFO",
    "request_id": "914f6104-538d-4ddc-beef-37bfe06ca1c7",
    "host": "127.0.0.1",
    "my_param": "param value",
    "user_id": "99",
    "my_custom_header": "some header value",
    "tags": [
        "TAG",
        "NESTED"
    ],
    "msg": "nested tagged log message"
}

If you really like tagging, this is a good move.

🤔 But are these things you're tagging really "tags" or should they be new keypairs? In a practical example, the code is more likely something like this:

Rails.logger.tagged("BillingJob") do
  Rails.logger.tagged("User #{user.id}").info("nested tagged log message")
end

and wouldn't that be better JSON as:

{
  "class": "BillingJob",
  "user": 1234
}

vs

{ "tags": ["BillingJob", "User 1234"] }

If you're nodding along, at this point, you're probably wondering whether maybe we should just write:

logger.info "nested message", user: 1234, class: "BillingJob"

If so, congratulations, you've just invented structured logging!

What's Structured Logging?​

As you can see, structured logging is pretty straightforward. It lets us do something like this:

log.info "hello", user: "1", team: "The best team"

# Text Log
# INFO hello user=1, team=The Best Team
# JSON Log
# {severity: INFO, message: "hello", user: 1, team: "The Best Team"}

Hey now, that really is better.

So, what libraries do this? Quite a few, actually. Here's what they look like:

logcraft​

logger = Logcraft.logger 'Application'

logger.info 'Log message'
# => {"timestamp":"2022-...","level":"INFO","logger":"Application","pid":80422,"message":"Log message"}

logger.info message: 'User logged in', user_id: 42
# => {"timestamp":"2022-...","level":"INFO","logger":"Application","pid":80422,"message":"User logged in","user_id":42}

I don't really dig having to say message: but it's not the end of the world. Logcraft has around 5k downloads on rubygems as of today.

ougai​

Here's an excerpt from the ougai docs:

logger.info('Information!')
#{"name":"main","hostname":"mint","pid":14607,"level":30,"time":"2016-10-16T22:26:48.835+09:00","v":0,"msg":"Information!"}

logger.info({
  msg: 'Request', method: 'GET', path: '/login',
  format: 'html', controller: 'LoginController',
  action: 'new', status: 200
})
#{"name":"main","hostname":"mint","pid":9044,"level":30,"time":"2016-10-28T17:58:53.668+09:00","v":0,"msg":"Request","method":"GET","path":"/login","format":"html","controller":"LoginController","action":"new","status":200}

Again with the msg: but it's not the end of the world. Ougai has around 8.4M downloads on rubygems as of today.

semantic_logger​

logger.debug('log this', foo: 'foo', bar: 'bar')
# Text
#DEBUG 2023-09-06 10:31:18 -0400: {foo: foo,bar: bar} log this
# JSON
{"named_tags":{"foo":"foo","bar":"bar"},"name":"Post","message":"log this"}

Semantic Logger has about 12M downloads, and there is also a rails_semantic_logger gem with Rails-specific integrations.

What About Lograge?​

Lograge is sort of a structured logger. It does output structured logs for your Rails requests, but it doesn't give you a way to structure your own logs. It's 101M downloads and a proven tool, but I'm not including it here because we're talking about structured logging and tagged logging in general.

So, is Tagged Logger worse than Structured Logging?​

Well, yes. Mostly. Honestly I didn't have an opinion before I really dug in and researched this, but in my view structured logging can give us the same benefits as tagged logging, but in a cleaner, more machine-readable way that fits better with modern log aggregators.

🤔 However there is one thing I found valuable with tagged logging and that is nested contexts. It’s a convenient way to propagate context instead of adding it to each log entry. Does using structured logging mean we have to give that up?

No! Fortunately, we can do this in SemanticLogger as well. It looks like this:

logger.tagged {user: 1} do
  logger.info "nested"
end

# Log Output
# nested user=1

Could it be better?​

My last gripe would be that I'm repeating this context. Isn't this the same context I'm using for my feature flags library, datadog, and sentry?

Sentry.configure_scope do |scope|
  scope.set_context(
    'user',
    {
      name: 'Bob Beemer',
      id: 1234,
    }
  )
end

Datadog.configure do |c|
  c.tags = { 'user_name' => 'Bob Beemer',
             'user_id' => '1234' }
end

context = LaunchDarkly::LDContext.create({
    key: "user-key-123abc",
    kind: "user",
    name: "Bob Beemer",
    id: 1234
})

$prefab.with_context({
      user: {
        key: current_user.tracking_id,
        id: current_user.id,
        name: current_user.name,
      }
    }, &block)

Why do I need to repeat this again for logging? Can't I just do it once?

The Ideal​

I ended up writing this post because we're working on a dynamic log library, and I wanted to make sure we had all our bases covered with respect to structured logging and tagged logging.

Semantic logger is pretty darn good, but if we're going to really DRY things up I could reuse the context I use for feature flags. Here's what that might look like.

# application_controller.rb
class ApplicationController < ActionController::Base

  around_action do |_, block|
    # Put our context together in one place for the whole request
    $prefab.with_context({
      user: {
        key: current_user.tracking_id,
        id: current_user.id,
        name: current_user.name,
      }
    }, &block)
  end
end

# application.rb
module MyApplication
  class Application < Rails::Application
    # tell the logger to add the values of these contexts to log messages
    logger.add_context_keys "user.id", "user.name"

    # or add extra logging context in a block
    logger.with_context {runtime: {value: 42}} do
      logger.info "hello"

       # Feature flag value evaluation uses existing context for user.id and runtime.value
       $prefab.get("my-feature-flag")
    end
  end
end

# Log Output
# INFO hello user.id=1234, user.name=Bob Beemer, runtime_value=42

Summary​

1. Tagged logging is nice.
   1. Tagged logging makes decent-looking console output.
   2. Tagged logging requires adding things manually.
   3. Tagged logging is a bit like structured logging, but in a way that log aggregators can't use.
2. Structured logging is better.
3. But ideally structured logging can also add structure in a block.
4. Semantic Logger is a great library that does this, and it's the same approach we're taking at Prefab.

Changing the log level in Java​

Programmatically changing the log level in Java is easy. The only up-front hitch is that you just can't do it via SLF4J -- you'll need to use the underlying logging framework.

Log4j has a Configurator class we can use and in Logback we simply get the logger and set the level. Here's what that looks like.

// Log4J
Configurator.setLevel(loggerName, Level.INFO);
 
// Logback
Logger logger = (Logger)LoggerFactory.getLogger(loggerName);
logger.setLevel(Level.INFO);

But that's not really why you're here, is it?

What you're actually after is changing the log level without restarting the application. What you're actually after is getting more debug information from a production system without having to redeploy or turn off excessive logging that is costing you money in log ingestion costs.

Changing the log level programmatically is only half the battle (or maybe a 1/10th the battle). In any real application, we now we need to figure out how this code gets called.

This challenge is more complex, but it breaks down into two big parts:

1. Where does the user input the logger and level?
2. How does this system broadcast this information to all services?

Capturing the user's desire to change the log level​

The developer wants more debug information about FooClass. How do we capture this intent? Collecting the changes comes in a few flavors.

An API request to change the levels​

Your developer can POST to an internal URL. Something like POST /log-levels?logger=com.example.FooClass&level=DEBUG would work. The question here will be how to broadcast this change to all instances of the service.

A JMX Request to change the levels​

Log4j supports JMX to trigger configuration reloads or edit the config file itself. There's even a client GUI! As with using an API request to a custom endpoint, that'll only work one application instance at a time.

A Shared File​

Your developer can edit a shared log4j.properties or logback.xml somewhere. This is the most common way to do this, but sharing the file around can be an annoying infrastructure challenge and the behavior if you corrupt the file is not always obvious. Log4j also supports (re)loading configuration from a URI which is still basically just a remote shared file or files.

A Centralized UI​

Maybe you build an internal UI or you use something like SpringBoot Admin or Prefab. The Spring Boot Admin UI looks like this:

The Prefab UI is similar, giving us a hierarchical view as well as some feedback on log volume at each level.

A centralized UI may or may not have knowledge about the loggers that you're using. Prefab has knowledge of both the logger name as well as the frequency they are being used so it is able to render this helpful UI. This is helpful so you don't have to correctly type the logger name, but also so you know how many message/sec are happening at each logger. To do this, you'll need to send aggregate telemetry back to a central location on logging calls.

Broadcasting the change to all instances of the service​

Once we've captured the intent to change the log level, we need to broadcast this change to all instances of the service. While some of the approaches like shared files or URI-based configuration will handle this easily, others like the API endpoint approach have shortcomings in this department. Hit that custom logging configuration API, and our load balancer delivered the POST to one instance of our service, and we changed the log level there. But... what about the other instances? Hope that was the one you wanted!

Broadcasting the changes is typically:

Ignoring this problem​

We could skip this step and ony changing the log levels on the one instance that received the user intent. Depending on your use case, this may be sufficient. If you only have a single instance, or you are just looking for a sampling of logs it should serve you well. If you have multiple instances or you are looking for a specific log message, this will not work and it may lead to confusion.

Service Discovery​

We could implement some type of service discovery to propagate the change to peer application instances. If each instance is aware of the other instances, then we can broadcast the change to all of them. It's unlikely you're going to want to build this out yourself just for this logging use case, but if this is technology you already have in place, it could be a reasonable option.

NFS File Sync / URI Sync​

Having our log4j.properties synced over something like NFS and setting clients to monitor/scan the file/URI for changes. Log4j uses <Configuration monitorInterval="30"> to refresh. In Logback this looks like <configuration scan="true" scanPeriod="30 seconds">.

This may be a reasonable option if you already have a shared file system in place, but wouldn't be the first choice for most people.

PubSub​

We can listening to a PubSub system for changes and programmatically configuring the logging system using the code above. Your API endpoint could publish a Redis pub/sub and all instances would listen for changes. Sandeep has a full fledged example of this (in Python) in route triggered state update across workers.

This is likely the easiest solution if you are going to DIY. Redis Pub/Sub is pretty easy to use. You'll need to decide on the message format, but it's a pretty straightforward solution.

One wrinkle is that the log level change will reset as instances reboot. Pub/Sub is fleeting. Instances that are listening at the time of the change will set their levels, but new instances that start afterwards will not see the change. If you want new instances to pick up the change, you'll need use something like Kafka or Redis Streams which will persist the message and allow new instances to pick up the change.

Filter & Dynamic Configuration​

The last option is a bit different. Rather than listen for changes and set the log level, we can use a log filter to decide whether or not to log a message and have this filter look up the current log level by looking into a dynamic configuration system.

This dynamic configuration system will use some form of pub sub to ensure its working from the most current configuration, so this could also be seen as a variation of #4, but it's distinct in that this pub/sub system is not a 1-off just for logging. This is what Prefab does, specifically, we use SSE to get the changes and then a Logback TurboFilter that looks up the current value. Pseudo code for this looks like:

 public FilterReply decide(
    Marker marker,
    Logger logger,
    Level level,
    String s,
    Object[] objects,
    Throwable throwable
) {
    Optional<Prefab.LogLevel> loglevelMaybe = dynamicConfig.getLogLevel(logger);
    if (loglevelMaybe.isPresent()) {
        Level calculatedMinLogLevelToAccept = LogbackLevelMapper.LEVEL_MAP.get(
            loglevelMaybe.get()
        );
        if (level.isGreaterOrEqual(calculatedMinLogLevelToAccept)) {
            return FilterReply.ACCEPT;
        }
        return FilterReply.DENY;
    }
    return FilterReply.NEUTRAL;
}