Fixed logging format

[c3ho]

Issue This PR Addresses

Fixes #1448

Type of Change

• Bugfix: Change which fixes an issue
• New Feature: Change which adds functionality
• Documentation Update: Change which improves documentation
• UI: Change which improves UI

Description

Now when logging to console, the log messages will look pretty again.

Could someone also test the pino-elastic logging as well for this and make sure it is also working? I tested it, but it was inconclusive for me.

Steps to test fix:

1. in the .env file set LOG_LEVEL to info
2. docker-compose up redis elasticsearch
3. npm start

Check info messages in terminal tab. They should look pretty now (just like before)

To regression test:

1. in the .env file set LOG_LEVEL to info and set LOG_ELASTIC to 1
2. docker-compose up redis elasticsearch
3. npm start, there should be no logging appearing in terminal tab anymore as they're directed to elasticsearch now
4. navigate to http://localhost:9200/_cat/indices?v You should see two rows and under the indexes column there should be 2 indexes logs and posts
5. Remember to set LOG_ELASTIC to blank again in your .env file after testing.

Checklist

• Quality: This PR builds and passes our npm test and works locally
• Tests: This PR includes thorough tests or an explanation of why it does not
• Screenshots: This PR includes screenshots or GIFs of the changes made or an explanation of why it does not (if applicable)
• Documentation: This PR includes updated/added documentation to user exposed functionality or configuration variables are added/changed or an explanation of why it does not(if applicable)

[humphd]

Looks good.

[c3ho]

@humphd Is it safe to assume we have should have an almost same amount of docs in logs and posts index generated when we use LOG_LEVEL=info?

I'm thinking a doc should be created in the logs index for each feed that we process(or skip)

[humphd]

@c3ho sorry, I don't follow what you're asking. Also, do you want to merge this?

[c3ho]

@humphd sorry I'm holding off on merging this because I'm testing the options part. It seems to not like prettyPrint as I'm unable to get the logs index to show.

What I wanted to ask was for example we have the following when you navigate to http://localhost:9200/_cat/indices?v:

with the original PR, we should have a new index called logs, if I have LOG_LEVEL=info set. Shouldn't the docs.count # be higher?

For quick reference this is after a few minutes of running:

I would expect the docs.count for logs to be higher since we'll have an INFO message for each feed being processed or skipped.

[humphd]

Yeah, that sounds odd to me (that it's so low). What do you see in logs when you get those 8?

[c3ho]

🤷 I'm still trying to figure out how to use kibana so I can look inside those logs

{
  "took" : 607,
  "timed_out" : false,
  "_shards" : {
    "total" : 1,
    "successful" : 1,
    "skipped" : 0,
    "failed" : 0
  },
  "hits" : {
    "total" : {
      "value" : 6723,
      "relation" : "eq"
    },
    "max_score" : 1.0,
    "hits" : [
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "dIeZAXYBHnRERHrlN5Jg",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:16.061Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Loading all feeds into feed queue for processing"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "dYeZAXYBHnRERHrlN5Jh",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:16.066Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Telescope listening on port 3000"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "doeZAXYBHnRERHrlN5Jh",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:16.599Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Connected to elasticsearch!"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "d4eZAXYBHnRERHrlN5Jh",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:16.601Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Starting 1 instance of feed processor."
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "eIeZAXYBHnRERHrlrJJ_",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:47.072Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Skipping invalid wiki feed url blog.cataldo.ca/index.php/category/open-source/feed?v=1 for author Luca  Cataldo"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "eYeZAXYBHnRERHrlrJJ_",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:47.073Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Skipping invalid wiki feed url https:https://robertbegnatechblog.wordpress.com/category/open-source/feed for author Robert Begna"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "eoeZAXYBHnRERHrlrJJ_",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:49:47.073Z",
          "pid" : 35640,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Skipping invalid wiki feed url https://danwithopensource.blogspot.com/feeds/posts/default/-/open source for author Name = Daniel Beigi"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "e4ehAXYBHnRERHrlFpLE",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:58:21.286Z",
          "pid" : 19112,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "[HTTP 200 - OK] Feed has new content: https://osd600.blogspot.com/feeds/posts/default/"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "fIehAXYBHnRERHrlFpLE",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:58:22.807Z",
          "pid" : 19112,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "[HTTP 304 - Not Modified] Feed not downloaded: http://cty6.wordpress.com/feed/"
        }
      },
      {
        "_index" : "logs",
        "_type" : "_doc",
        "_id" : "fYehAXYBHnRERHrlFpLE",
        "_score" : 1.0,
        "_source" : {
          "level" : 30,
          "time" : "2020-11-25T22:58:22.815Z",
          "pid" : 19112,
          "hostname" : "DESKTOP-UQT0U30",
          "msg" : "Skipping resource at https://klopez8.blogspot.com/feeds/posts/default/-/FilerJS. Feed previously marked invalid"
        }
      }
    ]
  }
}

[c3ho]

Nevermind, I got ~7k hits on logs just now.

[humphd]

It might be caching results and not flushing them to the db until some threshold is reached.

[c3ho]

I think that's the case with the flush-bytes setting.

[c3ho]

@humphd I put another ternary to check LOG_ELASTIC in .env if set we'll use { log: logLevel } instead of options (so pino-elastic actually works), if we're not logging to elastic we'll use options and keep prettyPrint