|
| 1 | +Detailed Bug Reporter |
| 2 | +===================== |
| 3 | + |
| 4 | +This is a tool to simplify the debugging of task-oriented Node.js processes. |
| 5 | + |
| 6 | +The core concept of this tool is that many common backend applications can be logically divided into |
| 7 | +a number of tasks or pipelines - e.g. handling a single HTTP request, processing a batch of data |
| 8 | +in a cron job etc. In an asynchronous environment, simply writing debug data to a log file from |
| 9 | +parallel tasks quickly results in a headache. Apply a little Debugr magic though, and the next bug |
| 10 | +that causes your app to crash will be found in minutes, if not seconds! |
| 11 | + |
| 12 | +Heavily inspired by [Tracy], although Debugr comes with its own unique perks. |
| 13 | +Written in TypeScript, so type declarations are included out of the box. |
| 14 | + |
| 15 | +## Installation |
| 16 | + |
| 17 | +Debugr consists of a core package and a number of plugins. `npm install` what you need according |
| 18 | +to your use-case: |
| 19 | + |
| 20 | + - [`@debugr/core`] - Boring, but necessary |
| 21 | + - [`@debugr/express`] - Express request & response logger |
| 22 | + - [`@debugr/typeorm`] - TypeORM SQL logger |
| 23 | + - [`@debugr/http-formatter`] - HTTP request & response formatter |
| 24 | + - [`@debugr/sql-formatter`] - SQL query formatter |
| 25 | + - [`@debugr/graphql-formatter`] - GraphQL query formatter |
| 26 | + |
| 27 | +Note that formatter plugins are usually installed and configured automatically with packages that |
| 28 | +generate data they can consume, e.g. the Express logger plugin will install and autoconfigure |
| 29 | +the HTTP formatter plugin. |
| 30 | + |
| 31 | +## Usage introduction |
| 32 | + |
| 33 | +This is an example of the raw core usage, just to show you the basics; with plugins a lot of the |
| 34 | +stuff will be done automatically for you. |
| 35 | + |
| 36 | +```typescript |
| 37 | +import { Logger, debugr } from '@debugr/core'; |
| 38 | + |
| 39 | +const debug = debugr({ |
| 40 | + logDir: __dirname + '/log', |
| 41 | +}); |
| 42 | + |
| 43 | +// At the start of a task you create a logger for the task: |
| 44 | +const logger: Logger = debug.createLogger(); |
| 45 | + |
| 46 | +// At any point inside your task you can write into the logger: |
| 47 | +logger.debug('A debug message'); |
| 48 | +logger.info('An info message with %d %s %s', [3, 'printf-style', 'params']); |
| 49 | +logger.warning({ custom: 'data', is: 'supported also' }); |
| 50 | +logger.error(new Error('Which shan\'t disappear without a trace!')); |
| 51 | +logger.log(Logger.INFO, 'Just so you know'); |
| 52 | + |
| 53 | +// At the end of your task you must call this: |
| 54 | +logger.flush(); |
| 55 | +``` |
| 56 | + |
| 57 | +This will produce a dump file in the log directory that will look something like this: |
| 58 | + |
| 59 | +![an example dump file] |
| 60 | + |
| 61 | +The way this tool is designed, *nothing* is logged at the time you call `logger.log()` or |
| 62 | +any of the shortcuts; instead, when you call `logger.flush()`, Debugr will check if at least |
| 63 | +one of the entries in the logger instance exceeded a (configurable) threshold. If there is |
| 64 | +at least one such entry, the logger will be flushed into an uniquely-named file in the log |
| 65 | +directory. |
| 66 | + |
| 67 | +Of course, if you want a specific task logged _always_, you can do so: just call |
| 68 | +`logger.markForWriting()` sometime between creating it and calling `logger.flush()`. |
| 69 | +Conversely, if your code can determine that a particular task doesn't need to be logged |
| 70 | +no matter how much things went wrong you can call `logger.markAsIgnored()`. |
| 71 | + |
| 72 | +The format of the name of the files written in the log directory is `{timestamp}--{id}.html`. |
| 73 | +`{timestamp}` is `YYYY-MM-DD-HH-II-SS` in UTC; `{id}` here represents an identifier |
| 74 | +of the logger instance. By default this identifier is generated from the log entry |
| 75 | +which caused the logger to be marked for writing; in some scenarios you may want to set it |
| 76 | +yourself, which you can do by means of `logger.setId()`. |
| 77 | + |
| 78 | +Last but not least, if you should neglect to call `logger.flush()` at the end of your task, |
| 79 | +Debugr will eventually realise something is amiss and flush the logger automatically, |
| 80 | +provided the Node.js process didn't yet exit. This is called garbage collection and is, |
| 81 | +of course, configurable. |
| 82 | + |
| 83 | +### `debugr` options |
| 84 | + |
| 85 | +| Option | Type | Default | Description | |
| 86 | +| ----------------- | ---------- | -------------- | ---------------------------------------------------------------------------- | |
| 87 | +| `logDir` | `string` | | Root directory for generated logs; this is the only required option | |
| 88 | +| `threshold` | `number` | `Logger.ERROR` | The minimum level a log entry must have to mark a logger for writing | |
| 89 | +| `cloneData` | `boolean` | `false` | Clone data of log entries using V8 serialize / deserialize | |
| 90 | +| `writeDuplicates` | `boolean` | `false` | Write dumps even if another dump with the same ID already exists | |
| 91 | +| `gc` | `object` | | Garbage collection options: | |
| 92 | +| `gc.interval` | `number` | `60` | How often GC will be run, in seconds | |
| 93 | +| `gc.threshold` | `number` | `300` | How long since a logger has last been touched before GC should auto-flush it | |
| 94 | +| `plugins` | `Plugin[]` | | An array of plugins | |
| 95 | + |
| 96 | +### `Logger` API |
| 97 | + |
| 98 | +The `Logger` instance obtained from `debug.createLogger()` has the following methods: |
| 99 | + |
| 100 | + - `log(level: number, data: Record<string, any>): void` |
| 101 | + `log(level: number, message: string, data?: Record<string, any>): void` |
| 102 | + `log(level: number, message: string, params?: any[], data?: Record<string, any>): void` |
| 103 | + |
| 104 | + This method pushes an arbitrary entry onto the logger's queue. There are four default |
| 105 | + log levels: `Logger.DEBUG`, `Logger.INFO`, `Logger.WARNING` and `Logger.ERROR`. Later |
| 106 | + you'll learn how you can use your own arbitrary log levels. |
| 107 | + |
| 108 | + The `message` string can contain `printf`-style placeholders like `%s`, `%.3f` etc. |
| 109 | + These will be processed only if `params` is specified. Internally this uses [`printj`], |
| 110 | + so see its documentation to check what is possible. |
| 111 | + |
| 112 | + The `data` argument can contain any arbitrary data you wish to include in your dump. |
| 113 | + However: by default only a _reference_ to the passed object is stored - meaning that |
| 114 | + the dump will contain a snapshot of the data at the moment `logger.flush()` is called. |
| 115 | + This should usually be okay; but if for some reason you need to you can turn on data |
| 116 | + cloning by setting the `cloneData` option to `true` when calling `debugr()`. If this |
| 117 | + option is set then the object passed to the `data` argument will be cloned using the |
| 118 | + V8 serialize / deserialize functions, which should be reasonably fast and supports |
| 119 | + complicated things like cyclic references and so on. |
| 120 | + |
| 121 | + - `debug(data: Record<string, any>): void` |
| 122 | + `debug(message: string, data?: Record<string, any>): void` |
| 123 | + `debug(message: string, params?: any[], data?: Record<string, any>): void` |
| 124 | + |
| 125 | + Shortcut for `logger.log(Logger.DEBUG, ...)`. |
| 126 | + |
| 127 | + - `info(data: Record<string, any>): void` |
| 128 | + `info(message: string, data?: Record<string, any>): void` |
| 129 | + `info(message: string, params?: any[], data?: Record<string, any>): void` |
| 130 | + |
| 131 | + Shortcut for `logger.log(Logger.INFO, ...)`. |
| 132 | + |
| 133 | + - `warning(data: Record<string, any>): void` |
| 134 | + `warning(message: string, data?: Record<string, any>): void` |
| 135 | + `warning(message: string, params?: any[], data?: Record<string, any>): void` |
| 136 | + |
| 137 | + Shortcut for `logger.log(Logger.WARNING, ...)`. |
| 138 | + |
| 139 | + - `error(data: Record<string, any>): void` |
| 140 | + `error(message: string, data?: Record<string, any>): void` |
| 141 | + `error(message: string, params?: any[], data?: Record<string, any>): void` |
| 142 | + |
| 143 | + Shortcut for `logger.log(Logger.ERROR, ...)`. |
| 144 | + |
| 145 | + - `setId(id: string): void` |
| 146 | + |
| 147 | + Sets the ID that will be used as part of the filename if the dump ends up |
| 148 | + getting written when `logger.flush()` is called. |
| 149 | + |
| 150 | + - `markForWriting(): void` |
| 151 | + |
| 152 | + Marks the logger for writing, i.e. when `logger.flush()` is called, the dump |
| 153 | + will be created regardless of whether an entry exceeding the threshold has |
| 154 | + been logged. |
| 155 | + |
| 156 | + - `markAsIgnored(): void` |
| 157 | + |
| 158 | + The inverse of `markForWriting()` - when `logger.flush()` is called, just |
| 159 | + forget the logger and don't write anything, no matter what has been logged. |
| 160 | + |
| 161 | + - `flush(): void` |
| 162 | + |
| 163 | + Writes the logger to the disk if an entry exceeding the threshold has been |
| 164 | + logged or if the logger has been marked for writing. |
| 165 | + |
| 166 | + |
| 167 | +[Tracy]: https://tracy.nette.org |
| 168 | +[`@debugr/core`]: ./packages/core |
| 169 | +[`@debugr/express`]: ./packages/express |
| 170 | +[`@debugr/typeorm`]: ./packages/typeorm |
| 171 | +[`@debugr/http-formatter`]: ./packages/http-formatter |
| 172 | +[`@debugr/sql-formatter`]: ./packages/sql-formatter |
| 173 | +[`@debugr/graphql-formatter`]: ./packages/graphql-formatter |
| 174 | +[an example dump file]: ./example.png |
| 175 | +[`printj`]: https://www.npmjs.com/package/printj |
0 commit comments