scribbles is a log and tracing lib for Node
MIT License
scribbles a log and tracing lib for Node
.trace(
will be automatically tagged, no matter where in your app it is.traceTrigger
to filter a set of logs to only when there is a threshold is met or exceededstdOut
to get a string of the entry OR dataOut
to get an enriched object representing the log eventYou should be running node v8.5.0+
npm install --save scribbles
yarn add scribbles
const scribbles = require('scribbles');
scribbles.log("hello world")
// myRepo:local:master [ ] 2022-06-27T16:24:06.473 #3d608bf <log> index.js:174 hello world
scribbles[logLevel](message, [value, [error]])
There is a config
that takes a configuration object.
console
repo
: The git repository name as it appears on the originbranch
: The current git branchhash
: Short git hash of current committime
: Time of logginglogLevel
: The logging level for this entryhostname
: The hostname of the operating system.instance
: a base16 value representing the current instancemode
: The environment your application is running in. e.g. local, dev, prod etc..
fileName
: The file namelineNumber
: The line in the filemessage
: Message to logvalue
: Values to logstackTrace
: The stack trace if an Error object was passedv
: The version of scribbles used to create this entry. This allows matching log body with parsers. As the layout may change with new versions.["error", "warn", "status", "log", "timer", "info", "debug"]
logLevel
to the start of the arraystring
of a header name to forwardRegExp
to match header names to forwardarray
of header names to forward. Can exact matching string
s and/or RegExp
s.null
to disable forwarding headersobject
of output keys with input selector values.string
OR array of strings
: that will be taken in order of preference to be selected(i.e. If an incoming request has a header named the same as first index. Ues that, else check the next index and so on)process.env
hash
: attribute name of git short hashrepo
: attribute name of git repository namebranch
: attribute name of git branchinlineCharacterLimit
[number]: Will inline values up to this length. ~ In Dev Mode, this will be set to the width of your terminal or default to 80
indent
[string]: preferred indentation. Defaults " "
~ 2 spaces
depth
[number]: This represents how many nested steps in the object/array tree are to be walkedsingleQuotes
[string]: Set to true to get single-quoted strings. Default: false
filter
(object, key) [function]: Expected to return a boolean of whether to include the property in the output.transform
(object, key, val) [function]: Expected to return a string that transforms the string that resulted from stringifying a given property.
Via package.json
Just add a "scribbles" attribute
{
"name": "myrepo",
"version": "0.0.0",
"main": "index.js",
"scripts": {
"test": "echo \"Error: no test specified\" && exit 1"
},
"dependencies": {
},
"scribbles":{
"mode":"test-runner",
"logLevel":"warn",
"levels":["danger", "error", "warn", "log", "info", "debug"],
"format":"{time} [{mode}#{hash}] <{logLevel}> {message}"
}
}
Via .config(...) function
scribbles.config({
mode:'test-runner',
logLevel:"warn", //only output warning messages or higher
levels:["danger", "error", "warn", "log", "info", "debug"],
format:'{time} [{mode}#{hash}] <{logLevel}> {message}'
})
scribbles.danger("hello world")
// 2022-06-27T16:24:06.473 [test-runner#3d608bf] <danger> hello world
There is also a option in config to set the dataOut
that will receive an object representing the log entry.
scribbles.config({
dataOut:function(data){
console.log(data);
}
})
scribbles.log("hello world")
/*{
v:"1.2.3",
git:{
repo:"myRepo",
branch:"master",
hash:"3d608bf"
},
trace:{
...
}
info:{
time:2022-06-27T16:24:06.473Z,
mode:"local",
hostname:"box",
logLevel:"log",
instance:"bfc977a"
},
context:{
fileName:"index.js",
lineNumber:174
},
input:{
message: "hello world"
},
}*/
π You can also poll the performance of your service. By calling scribbles.status(...)
This will attach an additional attribute to the dataOut and will not be available in stdOut.
state
: the state of the services. e.g. "up", "blocking"
cpu
: CPU info
cores
: number of available coresmodel
: description of the processorspeed
: MHz frequency speedpercUsed
: load on process as percentagepercFree
: available on process as percentagesys
: System info
startedAt
: when the system was startedarch
: platform architecture. e.g "x64"platform
: the operating system platformtotalMem
: the total megabytes of memory being usedfreeMem
: the total megabytes of memory freeusedMem
: the total megabytes of memory being usedprocess
: Node process info
percUsedCpu
: the percentage of processing power being used by this processpercFreeMem
: the percentage of memory being used by this processusedMem
: the total megabytes of memory being used by this processstartedAt
: when it's process was startedpTitle
: the current process title (i.e. returns the current value of ps)pid
: the ID of the processppid
: the ID of the current parent processuser
: node the name of the user who started nodevNode
: version of nodenetwork
: Networking info
port
: listening on this Portconnections
: number of current established connectionsscribbles.config({
dataOut:console.log
})
setInterval(function(){
scribbles.status();
}, 5000);
This will give you a performance snapshot every 5 seconds.
You can get Scribbles to store the Git info at build time, in order to show in the run time logs
Via webpack.config.js
Here is how to add git status to you logs.
//...
const ScribblesWithGitInBundle = require('scribbles/gitStatus');
//...
module.exports = {
//...
plugins: [
ScribblesWithGitInBundle,
// ...
]
//...
};
That's it!
process.env
.You can select then via the config opts.
Via package.js
{
...,
"scribbles":{
...,
"gitEnv": {
"hash":"GITHUB_SHA",
"repo":"GITHUB_REPOSITORY",
"branch":"GITHUB_REF"
}
}
}
Tip: If you are using Heroku, the git hash is storted in the "SOURCE_VERSION"
To get accurate file & line references when transpiling your code. You will need to enable inlining sourceMaps. There are two steps you need to add.
Generate source-map as part of the build
tsconfig.json
add "sourceMap": true
under "compilerOptions"Enable sourceMap support in Node
Node v12.12+ : can just add the --enable-source-maps
flag to the node command
OR
Node older : Will need to install NPM->source-map-support and add require('source-map-support').install()
to the top for you service
You can start a timer to calculate the duration of a specific operation. To start one, call the scribbles.timer(tag,[message])
function, giving it a name and an optional message. To stop the timer, just call the scribbles.timerEnd(tag,[message])
function, again passing the timer's name as the first parameter.
There are 3 functions:
scribbles.timer()
- Starts and/or logs the current value a timer based on the tag passed to the function.scribbles.timerEnd()
- logs the current value a timer and removes it, to be used later.scribbles.timer("Yo")
setTimeout(()=>{
scribbles.timer("Yo","123")
setTimeout(()=>{
scribbles.timerEnd("Yo","done!")
}, 300)
}, 400)
Output: You see the time it took to run the code
myRepo:local:master [ ] 2022-06-27T13:04:52.133 <timer> app.js:18 Yo (+0.00ms|0.00ms)
myRepo:local:master [ ] 2022-06-27T13:04:52.552 <timer> app.js:20 Yo:123 (+419.40ms|419.40ms)
myRepo:local:master [ ] 2022-06-27T13:04:52.875 <timerEnd> app.js:22 Yo:done! (+323.21ms|742.61ms)
When trying to debug a problem with logs that are intertwined. A stacktrace will give you limited information. You can see where the Error occurred and a message. However you cannot see the values as it flow through your system.
Using the trace system. Each log entry will be able to be connected, as it flows through your system.
To use the trace system you only need to pass in a root function that acts as the start of the execution. Everything that is executed within this function will be matched to the same trace ID, and name if provided.
scribbles.trace([label/opt,]next_fu)
The first argument to can be an options object. Here you can specify a spanLabel
to tag your entries, atraceId
& the tracestate
that are using in distributed tracing.
index.js
// for fun lets set a custom format for our logs
scribbles.config({format:`[{traceName} {spanId}] {message}`})
// an example of an event handler
function incoming(dataIn){
// wrap the work we want to do in `scribbles.trace`
scribbles.trace("eventstream",(spanId)=>{
// Event message logged from with here will have this correlation ID
// spanId = 090e8e40000005
workToDo(dataIn); // kick of the work
})
}
eventstream.js
function workToDo(dataIn){
// ...
// user scribbles as normal
scribbles.log("Doing something with the eventstream")
// [eventstream 090e8e40000005] Doing something with the eventstream
// ...
}
Log just the timeline of events you care about.
By setting a "traceTrigger" level. All scribbles calls within a trace context will respect it. If a call is make that matchs or exceds this level. Past, current & new events in this context will be outputted, else they will be suppressed
scribbles.config({
// Any call to error or higher will trigger all logs from logLevel for this specific this execution context
traceTrigger:"error",
// logLevel dont not have to be set. Will default to All
logLevel:'warning',
// Levels do not need to be set this is only for demonstration purposes
levels:['fatal','error','warning','info'],
})
scribbles.trace('in_trace',()=>{
scribbles.info(" --- Will NEVER be shown") // as this is below the logLevel
setTimeout(()=>{
// will be store, but will not be sent out at this point
scribbles.warning(" --- Wait")
setTimeout(()=>{
// traceTrigger exceded! store event will be sent out + this event
scribbles.fatal(" --- Now!")
setTimeout(()=>{
// will be sent out at the traceTrigger was already hit, for this *trace context*
scribbles.warning(" --- More!")
}, 500)
}, 500)
}, 500)
})
/*
myRepo:local:master [in_trace 3b3c6000000001] 2022-06-27T09:22:52.588 #3d608bf <warning> app.js:14 --- Wait
myRepo:local:master [in_trace 3b3c6000000001] 2022-06-27T09:22:52.890 #3d608bf <fatal> app.js:16 --- Now!
myRepo:local:master [in_trace 3b3c6000000001] 2022-06-27T09:22:53.199 #3d608bf <warning> app.js:18 --- More!
*/
in accordance with W3C trace-context
Distributed tracing is powerful and makes it easy for developers to find the causes of issues in highly-distributed microservices applications, as they track how a single interaction was processed across multiple services. But while tracing has exploded in popularity in recent years, there still isnβt much built-in support for it in languages, web frameworks, load balancers, and other components, which can lead to missing components or broken traces.
π€ Generating and attaching trace-context values to request headers is a standardized way of addressing this problem.
Instrumenting web frameworks, storage clients, application code, etc. to make tracing work out of the box. π₯³
const scribbles = require('scribbles');
const axios = require('axios');
const express = require('express');
scribbles.config({
headers:["X-Amzn-Trace-Id"]
});
const app = express();
// start a trace for each incoming request.
app.use(scribbles.middleware.express);
app.get('/', function (req, res){
scribbles.log("incoming");
// myRepo:local:master [198.10.120.12 090e8e40000005] 2022-06-27T16:24:06.473 #3d608bf <log> index.js:174 incoming
// Just by calling this other service normally, scribbles will inject the tracing headers
axios.get('https://some.domain.com/foo/')
.then(response => {
scribbles.log(response.data);
res.send("fin")
})
.catch(error => {
scribbles.error(error);
});
}) // END app.get '/'
app.listen(port, () => scribbles.status(`App is ready!`))
Example above is for axios but it will also work with http and request
It may look something like this
function traceMiddleware({headers}, res, next){
scribbles.trace({
// You can pass the traceparent as the traceId
// or you can pull the traceId from the traceparent and pass that
traceId:headers.traceparent,
tracestate:headers.tracestate,
// lets tag the current trace/span with the caller's IP
spanLabel:headers['x-forwarded-for']
},(spanId) => next());
} // END express
app.get('/', function (req, res){
scribbles.log("incoming");
// myRepo:local:master [198.10.120.12 090e8e40000005] 2022-06-27T16:24:06.473 #3d608bf <log> index.js:174 incoming
axios.get('https://some.domain.com/foo/',{
headers:scribbles.trace.headers() // tracing header IDs
})
.then(response => {
scribbles.log(response.data);
res.send("fin")
})
.catch(error => {
scribbles.error(error);
});
}) // END app.get '/'
small print:
MIT - If you use this module(or part), credit it in the readme of your project and failing to do so constitutes an irritating social faux pas. Besides this, do what you want with this code but don't blame me if it does not work. If you find any problems with this module, open issue on Github. However reading the Source Code is suggested for experience JavaScript and node engineer's and may be unsuitable for overly sensitive persons with low self-esteem or no sense of humour. Unless the word tnetennba has been used in it's correct context somewhere other than in this warning, it does not have any legal or grammatical use and may be ignored. No animals were harmed in the making of this module, although the yorkshire terrier next door is living on borrowed time, let me tell you. Those of you with an overwhelming fear of the unknown will be gratified to learn that there is no hidden message revealed by reading this warning backwards, I think.