More logging

.gitignore

@@ -2,3 +2,5 @@
 **/flow-typed
 **/flow-coverage
 **/out
+.env
+

chapter05/package-lock.json

@@ -1080,6 +1080,21 @@
                 }
             }
         },
+        "basic-auth": {
+            "version": "2.0.0",
+            "resolved": "https://registry.npmjs.org/basic-auth/-/basic-auth-2.0.0.tgz",
+            "integrity": "sha1-AV2z81PgLlY3d1X5YnQuiYHnu7o=",
+            "requires": {
+                "safe-buffer": "5.1.1"
+            },
+            "dependencies": {
+                "safe-buffer": {
+                    "version": "5.1.1",
+                    "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.1.1.tgz",
+                    "integrity": "sha512-kKvNJn6Mm93gAczWVJg7wH+wGYWNrDHdWvpUmHyEsgCtIwwo3bqPtV4tR5tuPaUhTOo/kvhVwd8XwwOllGYkbg=="
+                }
+            }
+        },
         "big-integer": {
             "version": "1.6.28",
             "resolved": "https://registry.npmjs.org/big-integer/-/big-integer-1.6.28.tgz",
@@ -1841,6 +1856,11 @@
                 "is-obj": "1.0.1"
             }
         },
+        "dotenv": {
+            "version": "5.0.1",
+            "resolved": "https://registry.npmjs.org/dotenv/-/dotenv-5.0.1.tgz",
+            "integrity": "sha512-4As8uPrjfwb7VXC+WnLCbXK7y+Ueb2B3zgNCePYfhxS1PYeaO1YTeplffTEcbfLhvFNGLAz90VvJs9yomG7bow=="
+        },
         "duplexer": {
             "version": "0.1.1",
             "resolved": "https://registry.npmjs.org/duplexer/-/duplexer-0.1.1.tgz",
@@ -4709,6 +4729,28 @@
                 "minimist": "0.0.8"
             }
         },
+        "morgan": {
+            "version": "1.9.0",
+            "resolved": "https://registry.npmjs.org/morgan/-/morgan-1.9.0.tgz",
+            "integrity": "sha1-0B+mxlhZt2/PMbPLU6OCGjEdgFE=",
+            "requires": {
+                "basic-auth": "2.0.0",
+                "debug": "2.6.9",
+                "depd": "1.1.2",
+                "on-finished": "2.3.0",
+                "on-headers": "1.0.1"
+            },
+            "dependencies": {
+                "debug": {
+                    "version": "2.6.9",
+                    "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+                    "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+                    "requires": {
+                        "ms": "2.0.0"
+                    }
+                }
+            }
+        },
         "ms": {
             "version": "2.0.0",
             "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz",
@@ -4910,6 +4952,11 @@
                 "ee-first": "1.1.1"
             }
         },
+        "on-headers": {
+            "version": "1.0.1",
+            "resolved": "https://registry.npmjs.org/on-headers/-/on-headers-1.0.1.tgz",
+            "integrity": "sha1-ko9dD0cNSTQmUepnlLCFfBAGk/c="
+        },
         "once": {
             "version": "1.4.0",
             "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz",

chapter05/package.json

@@ -75,10 +75,12 @@
     "dependencies": {
         "axios": "^0.18.0",
         "cors": "^2.8.4",
+        "dotenv": "^5.0.1",
         "express": "^4.16.3",
         "helmet": "^3.12.1",
         "jsonwebtoken": "^8.2.1",
         "mariasql": "^0.2.6",
+        "morgan": "^1.9.0",
         "winston": "^3.0.0-rc5"
     },
     "devDependencies": {

chapter05/serv_error.json.log

@@ -0,0 +1,2 @@
+{"message":"UNKNOWN ROUTE /invented","level":"warn"}
+{"message":"GENERAL ERROR res.say_xyzzy is not a function\nTypeError: res.say_xyzzy is not a function\n    at app.get (/home/fkereki/MODERNJS/chapter05/out/morgan_in_winston_server.js:67:9)\n    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)\n    at next (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/route.js:137:13)\n    at Route.dispatch (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/route.js:112:3)\n    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)\n    at /home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:281:22\n    at Function.process_params (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:335:12)\n    at next (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:275:10)\n    at logger (/home/fkereki/MODERNJS/chapter05/node_modules/morgan/index.js:144:5)\n    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)","level":"error"}

chapter05/serv_error.txt.log

@@ -0,0 +1,13 @@
+2018-05-28T20:04:04.479Z [serv] warn UNKNOWN ROUTE /invented
+2018-05-28T20:04:07.641Z [serv] error GENERAL ERROR res.say_xyzzy is not a function
+TypeError: res.say_xyzzy is not a function
+    at app.get (/home/fkereki/MODERNJS/chapter05/out/morgan_in_winston_server.js:67:9)
+    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)
+    at next (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/route.js:137:13)
+    at Route.dispatch (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/route.js:112:3)
+    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)
+    at /home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:281:22
+    at Function.process_params (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:335:12)
+    at next (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/index.js:275:10)
+    at logger (/home/fkereki/MODERNJS/chapter05/node_modules/morgan/index.js:144:5)
+    at Layer.handle [as handle_request] (/home/fkereki/MODERNJS/chapter05/node_modules/express/lib/router/layer.js:95:5)

chapter05/src/morgan_in_winston_server.js

@@ -0,0 +1,84 @@
+/* @flow */
+"use strict";
+
+const express = require("express");
+const winston = require("winston");
+const morgan = require("morgan");
+
+const app = express();
+
+const logger = winston.createLogger({
+    transports: [
+        new winston.transports.Console({
+            level: "info",
+            format: winston.format.combine(
+                winston.format.colorize({ all: true }),
+                winston.format.label({ label: "serv" }),
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [${msg.label}] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.txt.log",
+            level: "warn",
+            format: winston.format.combine(
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [serv] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.json.log",
+            level: "warn"
+        })
+    ]
+});
+
+app.use(
+    morgan(
+        `:method :url (:status) :res[content-length] - :response-time ms`,
+        {
+            stream: {
+                write: message => logger.info(message.trim())
+            }
+        }
+    )
+);
+
+app.get("/", (req, res) => {
+    logger.info("Doing some processing...");
+    logger.debug("Some fake step 1; starting");
+    logger.debug("Some fake step 2; working");
+    logger.debug("Some fake step 3; finished!");
+    res.send("Winston server!");
+});
+
+app.get("/xyzzy", (req, res) => {
+    logger.info("Adventurer says 'XYZZY'");
+    res.say_xyzzy(); // this will fail
+    res.send("Nothing happens.");
+});
+
+app.use((req, res) => {
+    logger.warn(`UNKNOWN ROUTE ${req.originalUrl}`);
+    res.status(404).send("NOT FOUND");
+});
+
+// eslint-disable-next-line no-unused-vars
+app.use((err, req, res, next) => {
+    logger.error(`GENERAL ERROR ${err.message}\n${err.stack}`);
+    res.status(500).send("INTERNAL SERVER ERROR");
+});
+
+app.listen(8080, () => {
+    logger.info("Ready at http://localhost:8080");
+});

chapter05/src/morgan_server.1.js

@@ -0,0 +1,100 @@
+/* @flow */
+"use strict";
+
+const express = require("express");
+const winston = require("winston");
+const morgan = require("morgan");
+const fs = require("fs");
+
+const app = express();
+
+const logger = winston.createLogger({
+    transports: [
+        new winston.transports.Console({
+            level: "info",
+            format: winston.format.combine(
+                winston.format.colorize({ all: true }),
+                winston.format.label({ label: "serv" }),
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [${msg.label}] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.txt.log",
+            level: "warn",
+            format: winston.format.combine(
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [serv] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.json.log",
+            level: "warn"
+        })
+    ]
+});
+
+const morganStream = fs.createWriteStream("serv_http_errors.log", {
+    flags: "a"
+});
+
+app.use(
+    morgan(
+        (tokens, req, res) =>
+            `${new Date().toISOString()} [http] ` +
+            `${tokens.method(req, res)} ${tokens.url(req, res)}`,
+        {
+            immediate: true,
+            stream: morganStream
+        }
+    )
+);
+
+app.use(
+    morgan(
+        `:date[iso] [http] ` +
+            `:method :url (:status) :res[content-length] - :response-time ms`,
+        {
+            skip: (req, res) => res.statusCode < 400
+        }
+    )
+);
+
+app.get("/", (req, res) => {
+    logger.info("Doing some processing...");
+    logger.debug("Some fake step 1; starting");
+    logger.debug("Some fake step 2; working");
+    logger.debug("Some fake step 3; finished!");
+    res.send("Winston server!");
+});
+
+app.get("/xyzzy", (req, res) => {
+    logger.info("Adventurer says 'XYZZY'");
+    res.say_xyzzy(); // this will fail
+    res.send("Nothing happens.");
+});
+
+app.use((req, res) => {
+    logger.warn(`UNKNOWN ROUTE ${req.originalUrl}`);
+    res.status(404).send("NOT FOUND");
+});
+
+// eslint-disable-next-line no-unused-vars
+app.use((err, req, res, next) => {
+    logger.error(`GENERAL ERROR ${err.message}\n${err.stack}`);
+    res.status(500).send("INTERNAL SERVER ERROR");
+});
+
+app.listen(8080, () => {
+    logger.info("Ready at http://localhost:8080");
+});

chapter05/src/morgan_server.js

@@ -0,0 +1,100 @@
+/* @flow */
+"use strict";
+
+const express = require("express");
+const winston = require("winston");
+const morgan = require("morgan");
+const fs = require("fs");
+
+const app = express();
+
+const logger = winston.createLogger({
+    transports: [
+        new winston.transports.Console({
+            level: "info",
+            format: winston.format.combine(
+                winston.format.colorize({ all: true }),
+                winston.format.label({ label: "serv" }),
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [${msg.label}] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.txt.log",
+            level: "warn",
+            format: winston.format.combine(
+                winston.format.timestamp(),
+                winston.format.printf(
+                    msg =>
+                        `${msg.timestamp} [serv] ${msg.level} ${
+                            msg.message
+                        }`
+                )
+            )
+        }),
+        new winston.transports.File({
+            filename: "serv_error.json.log",
+            level: "warn"
+        })
+    ]
+});
+
+const morganStream = fs.createWriteStream("serv_http_errors.log", {
+    flags: "a"
+});
+
+app.use(
+    morgan(
+        (tokens, req, res) =>
+            `${new Date().toISOString()} [http] ` +
+            `${tokens.method(req, res)} ${tokens.url(req, res)}`,
+        {
+            immediate: true,
+            stream: morganStream
+        }
+    )
+);
+
+app.use(
+    morgan(
+        `:date[iso] [http] ` +
+            `:method :url (:status) :res[content-length] - :response-time ms`,
+        {
+            skip: (req, res) => res.statusCode < 400
+        }
+    )
+);
+
+app.get("/", (req, res) => {
+    logger.info("Doing some processing...");
+    logger.debug("Some fake step 1; starting");
+    logger.debug("Some fake step 2; working");
+    logger.debug("Some fake step 3; finished!");
+    res.send("Winston server!");
+});
+
+app.get("/xyzzy", (req, res) => {
+    logger.info("Adventurer says 'XYZZY'");
+    res.say_xyzzy(); // this will fail
+    res.send("Nothing happens.");
+});
+
+app.use((req, res) => {
+    logger.warn(`UNKNOWN ROUTE ${req.originalUrl}`);
+    res.status(404).send("NOT FOUND");
+});
+
+// eslint-disable-next-line no-unused-vars
+app.use((err, req, res, next) => {
+    logger.error(`GENERAL ERROR ${err.message}\n${err.stack}`);
+    res.status(500).send("INTERNAL SERVER ERROR");
+});
+
+app.listen(8080, () => {
+    logger.info("Ready at http://localhost:8080");
+});

chapter05/src/winston_server.js

@@ -2,18 +2,17 @@
 "use strict";
 
 const express = require("express");
-const app = express();
-
 const winston = require("winston");
 
-const logger = winston.createLogger({
+const app = express();
-    level: "info",
 
+const logger = winston.createLogger({
     transports: [
         new winston.transports.Console({
+            level: "info",
             format: winston.format.combine(
                 winston.format.colorize({ all: true }),
-                winston.format.label({ label: "w_s" }),
+                winston.format.label({ label: "serv" }),
                 winston.format.timestamp(),
                 winston.format.printf(
                     msg =>
@@ -24,43 +23,55 @@ const logger = winston.createLogger({
             )
         }),
         new winston.transports.File({
-            filename: "w_s_error.txt.log",
+            filename: "serv_error.txt.log",
-            level: "error",
+            level: "warn",
             format: winston.format.combine(
                 winston.format.timestamp(),
                 winston.format.printf(
-                    msg => `${msg.timestamp} ${msg.level} ${msg.message}`
+                    msg =>
+                        `${msg.timestamp} [serv] ${msg.level} ${
+                            msg.message
+                        }`
                 )
             )
         }),
         new winston.transports.File({
-            filename: "w_s_error.json.log",
+            filename: "serv_error.json.log",
-            level: "error"
+            level: "warn"
         })
     ]
 });
 
-logger.level = "debug";
+app.use((req, res, next) => {
-
+    logger.info(`${req.method} request for ${req.originalUrl}`);
-logger.error("This is an error");
+    next();
-logger.info("This is an info");
+});
-logger.warn("This is a warning");
-logger.debug("This is debugging info");
 
 app.get("/", (req, res) => {
-    logger.info("Request for root /");
+    logger.info("Doing some processing...");
+    logger.debug("Some fake step 1; starting");
+    logger.debug("Some fake step 2; working");
+    logger.debug("Some fake step 3; finished!");
     res.send("Winston server!");
 });
 
-app.get("*", (req, res) => {
+app.get("/xyzzy", (req, res) => {
-    logger.error(`UNKNOWN ROUTE ${req.originalUrl}`);
+    logger.info("Adventurer says 'XYZZY'");
+    res.say_xyzzy(); // this will fail
+    res.send("Nothing happens.");
+});
+
+app.use((req, res) => {
+    logger.warn(`UNKNOWN ROUTE ${req.originalUrl}`);
     res.status(404).send("NOT FOUND");
 });
 
 // eslint-disable-next-line no-unused-vars
 app.use((err, req, res, next) => {
-    logger.error(`GENERAL ERROR ${err.message}`);
+    logger.error(`GENERAL ERROR ${err.message}\n${err.stack}`);
     res.status(500).send("INTERNAL SERVER ERROR");
 });
 
-app.listen(8081, () => logger.info("Ready at http://localhost:8080"));
+app.listen(8080, () => {
+    logger.info("Ready at http://localhost:8080");
+});