Deno by example: Content server — Part 5 Logging, tracking & documenting

Welcome to the medium course:

Learn Deno by example — Content server.

This is a medium course that takes the user from writing, testing, formatting, logging, documenting, and deploying an application in Deno. This rapid course consists of six sections.

Here are the course contents:

• Section 1: Introduction to content server
• Section 2: Formatting & linting
• Section 3: Unit testing
• Section 4: Integration & performance testing
• Section 5: Logging, tracking & documenting (this article)
• Section 6: Deployment on Deno Deploy

In section 1, we’ve gone through the content server application along with some manual tests. In section 2, we’ve used Deno’s built-in formatter and linter to improvise on the content server application. In section 3, we’ve identified, and written unit tests to test the smallest possible units in the application. In section 4, we’ve written integration & basic performance tests to validate the application as a black box. In this section, we’ll go over other aspects like logging, tracking, and documenting. We’re progressively enhancing the application. It’s advisable to read sections 1, 2, 3, & 4 before proceeding with this section. Let’s get started!

Logging

Any application is incomplete without logging. The application that we’ve developed so far doesn’t produce any logs. Although the application is very simple, it would still be tough to debug simple production issues like server didn’t respond with a file. In this step, we’ll add a logger & logs to the application.

Standard logger

There are numerous loggers in the market. Their purpose is more or less the same:

• Allow logging streams (stdout, file, etc.)
• Allow logging levels (critical to debug)
• Allow log file rotations when some condition is reached, remove older log files
• Allow custom logging formats
• etc.

Deno’s standard library comes with a logger module that supports all the above features. We’ll be using it as the logger for the content server application. To get a detailed idea about the standard library’s logger module, check out the article here.

Here is the code for a very basic logger in Deno:

• All log messages are sent to a file /var/tmp/log/contentServer.log
• Each file goes up to 100K in size
• Up to three backup log files (.1, .2, & .3)
• A custom formatter that logs in JSON

The following is the code of the new logger module:

//logger.ts
import { getLogger, handlers, setup } from "https://deno.land/std/log/mod.ts";
await setup({
    handlers: {
        fileHandler: new handlers.RotatingFileHandler("DEBUG", {
            filename: "/var/tmp/log/contentServer.log",
            maxBytes: 100000,
            maxBackupCount: 3,
            formatter: rec => JSON.stringify({region: rec.loggerName, ts: rec.datetime, level: rec.levelName, data: rec.msg})
        }),
    },
    loggers: {
        default: {
            level: "DEBUG",
            handlers: ["fileHandler"],
        },
    },
});
export const log = getLogger();

For efficiency of I/O operations, Deno’s standard logger buffers debug logs till:

• The buffer is full (4K bytes), or
• A critical log is written

Once either of the above conditions are met, the buffered logs are flushed on the disk.

Adding logs

The content server application is pretty straightforward. Due to the simplicity, we’ll add the logs only to a couple of places:

• Router: Logs all the request URL, response code, response length
• Controller: Exceptions raised by the file service

First, let’s update the router code with additional error handling & logging of all requests and responses.

//router.ts
export async function route(req: Request): Promise<Response> {
    let resp:Response;
    try {
        if (req.method !== "GET") {
            resp=new Response(null, { status: Status.MethodNotAllowed });
        } else {
            resp=await handleRequest(req);
        }
    } catch(err) {
        log.critical(`Router caught error: ${err.message}`);
        resp=new Response(null, {status: Status.InternalServerError});
    }
    log.info(
        `${req.method} ${req.url} ${resp.status} ${
            resp.headers.has("content-length")
                ? resp.headers.get("content-length")
                : 0
        } bytes`,
    );
    return resp;
}

Now, let’s update the controller code. The only line we’re adding is to print the exception raised by the file service:

//controller.ts
export async function handleRequest(req: Request): Promise<Response> {
    ... //code omitted
    try {
        ... //code omitted
    } catch (err) {
        log.critical("Caught exception", err.message);
        ... //code omitted
    }
    ... //code omitted
}

Let’s make a curl request to test it out:

$ curl http://localhost:8080/data/textFile.txt -H 'Authorization: Bearer cba633d4-59f3-42a5-af00-b7430c3a65d8'
Learning Deno Is Fun!

The log files are located at /var/tmp/log:

$ ls -ltr
-rw-r--r--  1 mayankc  wheel  9889 Nov 29 22:22 contentServer.log.3
-rw-r--r--  1 mayankc  wheel  9916 Nov 29 22:23 contentServer.log.2
-rw-r--r--  1 mayankc  wheel  9889 Nov 29 22:25 contentServer.log.1
-rw-r--r--  1 mayankc  wheel  4096 Nov 29 22:25 contentServer.log

The main log file is contentServer.log, while the backup files have extensions ending with .1, .2, and .3.

Here is a log statement:

{"region":"default","ts":"2021-11-30T06:25:41.315Z","level":"INFO","data":"GET http://localhost:8080/data/textFile.txt 200 22 bytes"}
{"region":"default","ts":"2021-11-30T06:38:45.528Z","level":"INFO","data":"POST http://localhost:8080/data/textFile.txt 405 0 bytes"}

For error cases, like file not found, the logs will look like:

{"region":"default","ts":"2021-11-30T20:48:46.568Z","level":"CRITICAL","data":"Caught exception No such file or directory (os error 2), stat './test/unit//data/inexistentFile.txt'"}

That’s all about logging. Let’s move to the next subsection, tracking.

Tracking

In the above subsection, we’ve added logs that could help in debugging issues. The logs have all the required information, but they lack correlation with a request. In other words, there is no way to track a request to a particular error. This is mandatory for high performance production grade applications.

In this subsection, we’ll learn how to add a tracking ID to all the requests & responses.

Tracking ID

A tracking ID is a simple v4 UUID (or any other random string) that:

• is allocated when the request arrives
• is present in all logs relevant to the request
• is sent back in the response

With tracking ID, the relevant logs can be checked for debugging of issues. A simple tracking ID can be created using the following API:

await crypto.randomUUID(); //9dde47c9-7cca-41ba-ae63-8dbd5ca164d6

Let’s update the code with tracking ID.

Adding tracking ID

There are a number of changes we need to make to support correlation via tracking ID.

First, we’ll introduce a new module called utils.ts that contains a utility API appendID(). This API will append a header (x-tracking-id) to the response object.

//utils.ts
export async function appendId(resp: Response, id: string) {
    if (!resp) {
        return;
    }
    resp.headers.set("x-tracking-id", id);
}

The tracking ID will be allocated in the router module and should be passed to subsequent modules so that all the logs contain the same tracking ID. The request object is read only, so it can’t be enhanced with tracking ID. An easy way to pass tracking ID and other information (if needed in future) is through a CustomRequest interface:

export interface CustomRequest {
    id: string;
    req: Request;
}

For now, the CustomRequest interface consists of just two fields:

• id: the tracking ID
• req: the original Request object

This way is flexible and allows passing more information without changing the interface. Note that, tracking ID is passed to further modules only for logging purposes. Except for router, further modules are not expected to add this tracking ID to the response. This work will be done only by the router.

Next, let’s update the router code with:

• tracking ID allocation
• passing tracking ID to controller
• appending tracking ID to response

//router.ts
import { Status } from "https://deno.land/std/http/http_status.ts";
import { CustomRequest, handleRequest } from "./controller.ts";
import { log } from "./logger.ts";
import { appendId } from "./utils.ts";
export async function route(req: Request): Promise<Response> {
    let resp: Response;
    const id = await crypto.randomUUID();
    try {
        if (req.method !== "GET") {
            resp = new Response(null, { status: Status.MethodNotAllowed });
        } else {
            resp = await handleRequest({ id, req } as CustomRequest);
        }
    } catch (err) {
        log.critical(`${id} Router caught error: ${err.message}`);
        resp = new Response(null, { status: Status.InternalServerError });
    }
    appendId(resp, id);
    log.info(
        `${id} ${req.method} ${req.url} ${resp.status} ${
            resp.headers.has("content-length")
                ? resp.headers.get("content-length")
                : 0
        } bytes`,
    );
    return resp;
}

Finally, let’s update the controller code to receive and add tracking ID to logs:

//controller.ts
export interface CustomRequest {
    id: string;
    req: Request;
}
export async function handleRequest(request: CustomRequest): Promise<Response> {
    const req: Request = request.req;
    const relativePath = (new URL(req.url)).pathname;
    if (!authorize(req.headers)) {
        return new Response(null, { status: Status.Unauthorized });
    }
    try {
        const { len, content } = await getContent(relativePath);
        return new Response(content, {
            status: 200,
            headers: {
                "content-length": len.toString(),
                "content-type": getCT[ext(relativePath)] || rawCT,
            },
        });
    } catch (err) {
        log.critical(`${request.id} Caught exception ${err.message}`);
        if (err instanceof Deno.errors.NotFound) {
            return new Response(null, { status: Status.NotFound });
        }
        if (err instanceof Deno.errors.BadResource) {
            return new Response(null, { status: Status.UnprocessableEntity });
        }
    }
    return new Response(null, { status: Status.InternalServerError });
}

That should be all. It’s time to run some tests.

$ curl http://localhost:8080/data/someRandomFile.txt -H 'Authorization: Bearer cba633d4-59f3-42a5-af00-b7430c3a65d8'
< HTTP/1.1 404 Not Found
< x-tracking-id: 7977644f-47af-4d4d-ba5f-dc2f2a16aaa8
< content-length: 0

The tracking ID comes in the response. Here are the relevant logs:

{"region":"default","ts":"2021-11-30T20:48:46.568Z","level":"CRITICAL","data":"7977644f-47af-4d4d-ba5f-dc2f2a16aaa8 Caught exception No such file or directory (os error 2), stat './test/unit//data/someRandomFile.txt'"}
{"region":"default","ts":"2021-11-30T20:48:46.569Z","level":"INFO","data":"7977644f-47af-4d4d-ba5f-dc2f2a16aaa8 GET http://localhost:8080/data/someRandomFile.txt 404 0 bytes"}

Let’s run the same for a successful case:

$ curl http://localhost:8080/data/textFile.txt -H 'Authorization: Bearer cba633d4-59f3-42a5-af00-b7430c3a65d8'
< HTTP/1.1 200 OK
< content-length: 22
< content-type: text/plain
< x-tracking-id: 59c9695c-f872-477d-aac9-9784a705ef90
Learning Deno Is Fun!

The relevant logs are:

{"region":"default","ts":"2021-11-30T20:51:08.466Z","level":"INFO","data":"59c9695c-f872-477d-aac9-9784a705ef90 GET http://localhost:8080/data/textFile.txt 200 22 bytes"}

That’s all about tracking ID. We’ll take a look at the full application right after the final subsection, documenting.

Documenting

Our content server application is quite simple with a few small modules containing up to 1 or 2 exports. This makes it easier to directly read the code and understand the APIs, inputs, and outputs. However, the task gets very tough when there are a large number of modules exporting a number of public APIs. It’ll be get tougher to understand directly from code.

Module level documentation is helpful for such cases. At the very least, all the public APIs should be documented with a description, inputs, & outputs.

Deno comes with a built-in documentation generator that supports the popular documentation format, JSDoc. The documentation can be fetched using command-line:

$ deno doc someModule.ts
Defined in file:///var/tmp/someModule.ts:1:0
async function someAPI(name:string): Promise<UserRecord>

The deno doc command can also be used to get the documentation of built-in modules, like:

$ deno doc --builtin Deno.readTextFile
Defined in deno://lib.deno.d.ts:1554:2
function readTextFile(path: string | URL, options?: ReadFileOptions): Promise<string>
  Asynchronously reads and returns the entire contents of a file as utf8
   encoded string. Reading a directory throws an error.
  
  ```ts
  const data = await Deno.readTextFile("hello.txt");
  console.log(data);
  ```
  
  Requires `allow-read` permission.

In this subsection, we’ll add some short & simple documentation to our modules like router, controller, authService & fileService.

Adding documentation

As mentioned earlier, deno supports JSDoc style documentation. JSDoc’s own documentation with examples can be seen here. As JSDoc is very well known, we’ll jump directly to our code.

//router.ts
/** @module Router */
/**
 * Routes the incoming Request to appropriate controller & sends the Response back to the caller
 */
export async function route(req: Request): Promise<Response> {
    ... //omitted
}

A description of the API is enough in our case. The inputs & outputs are anyways printed by deno.

$ deno doc router.ts
Defined in file:///Users/mayankc/Work/source/deno-course-content-server/router.ts:11:0
async function route(req: Request): Promise<Response>
  Routes the incoming Request to appropriate controller & sends the Response back to the caller

Next, we’ll add documentation to the handleRequest() API of the controller:

//controller.ts
/** @module Controller */
/** The CustomRequest interface */
export interface CustomRequest {
    /** Tracking ID */
    id: string;
    /** Original Request object */
    req: Request;
}
/**
 * Processes the incoming Request in two steps: 
 * 1) Checks if authorized to access the resource 
 * 2) Gets the resource
 * A Response object is sent back to the caller.
 */
export async function handleRequest(request: CustomRequest): Promise<Response> {
    ... //omitted
}

Let’s print the documentation for this module:

$ deno doc ./controller.ts 
Defined in file:///Users/mayankc/Work/source/deno-course-content-server/controller.ts:27:0
async function handleRequest(request: CustomRequest): Promise<Response>
  Processes the incoming Request in two steps: 
  1) Checks if authorized to access the resource 
  2) Gets the resource
  A Response object is sent back to the caller.
Defined in file:///Users/mayankc/Work/source/deno-course-content-server/controller.ts:14:0
interface CustomRequest
  The CustomRequest interface
id: string
  Tracking ID
req: Request
  Original Request object

Next, we’ll add documentation to the authorize() API of authService:

/** @module AuthService */
/** Authorizes the request by performing checks on the Authorization header's bearer token:
 * 1) If API keys are not provisioned or includes token, it's authorized (true)
 * 2) Unauthorized, otherwise (false)
*/
export function authorize(headers: Headers):boolean {
    ... //omitted
}

Let’s print the documentation for this module:

$ deno doc authService.ts 
Defined in file:///Users/mayankc/Work/source/deno-course-content-server/authService.ts:16:0
function authorize(headers: Headers): boolean
  Authorizes the request by performing checks on the Authorization header's bearer token:
  1) If API keys are not provisioned or includes token, it's authorized (true)
  2) Unauthorized, otherwise (false)

Lastly, let’s add the documentation to the getContent() API of the fileService module:

/** @module FileService */
/**  
 * Opens the given path with respect to the base path, and returns:
 * len - The length of the file
 * content - The stream of the file
*/
export async function getContent(relativePath: string) {
    ... //omitted
}

Let’s print the documentation for this module:

$ deno doc fileService.ts 
Defined in file:///Users/mayankc/Work/source/deno-course-content-server/fileService.ts:11:0
async function getContent(relativePath: string)
  Opens the given path with respect to the base path, and returns:
  len - The length of the file
  content - The stream of the file

That’s all about documentation. As the application is simple & straightfoward, there isn’t a lot of APIs to document.

Final code

We’ve finished our content server application with the following:

• Basic content server code with optional authorization
• Formatted and linted the application
• Written unit tests
• Written integration & performance tests
• Enhanced with logging & tracking
• Added basic documentation

The final application code is:

We’re done with the fifth section of the course.

Here is the map of this rapid medium course:

• Section 1: Introduction to content server
• Section 2: Formatting & linting
• Section 3: Unit testing
• Section 4: Integration & performance testing
• Section 5: Logging, tracking & documenting (this article)
• Section 6: Deployment on Deno Deploy

In the next and final section, we’ll deploy & run the content server application on Deno Deploy.