bcgov / nr-fom

Forestry Operations Map
Apache License 2.0
0 stars 1 forks source link

Implement MVP for FOM Reporting Requirement #331

Open ArogeG opened 1 year ago

ArogeG commented 1 year ago

Describe the task

Acceptance Criteria

Additional context

ArogeG commented 1 year ago

Include Jackson Porreca in the meeting with Julius on the FOM Reporting Requirement

basilv commented 1 year ago

See #330 for task list

basilv commented 1 year ago

More tips from other teams: https://github.com/bcgov/common-document-generation-service/blob/master/openshift/fluent-bit.cm.yaml#L76 https://github.com/bcgov/common-document-generation-service/blob/master/openshift/app.dc.yaml#L102

ianliuwk1019 commented 1 year ago

For log rotation, specifically for "Pino", these two choices seem popular:

basilv commented 1 year ago

Thanks Ian, logrotate is what I'd likely lean towards as it is likely far simpler to set up, but can you link that 'complication related to log truncation' issue?

ianliuwk1019 commented 1 year ago

Sounds good, I will try "logrotate" setup. The pino doc link mentions the truncate issue here: https://getpino.io/#/docs/help?id=rotate. image.png

basilv commented 1 year ago

As I figured, this won't be a significant issue particularly if we have log rotation trigger late at night.

basilv commented 1 year ago

I looked into tee and it might not work with logrotate, in which case what would work is to tail the output file. e.g. something roughly like this: entrypoint: tail -f app.log; node main.js > logrotate

ianliuwk1019 commented 1 year ago

Hi @basilv , As you might already feel that, nestjs-pino is a bit confusing on how to set it right and working. Although initially we worked out pino configuration to output log to both "stdout" and "file" but I was having trouble using similar configuration with the help of "ECS" package (@elastic/ecs-pino-format) to output ECS format to both stdout and file. I finally got ECS to work with "nestjs-pino" logger and output to stdout and a file. For it to work, two things changed:

ianliuwk1019 commented 1 year ago

Hi @basilv For using "logrotate", I spent more than a day last week (although more than half day was trying to figure out running Dockerfile(s) db/api individually and locally so I don't need to deploy logrotate setting on Openshift), getting some progress but not good enough yet to start logrotate manually. To really work out 'logrotate' it seem there are quite some pieces need to be involved:

I did try build/run Dockerfile locally to produce api containers and 'exec -it" to the container to execute logrotate command for FOM logrotate setting as "root". The command I tried can be executed, then I experimented from api to create more log lines, wait for sometime but I don't see log being rotated. So then I tried executing logrotate command again and it created a rotated file. That's why I feel either I didn't configure it right or it needs "cron" to assist logrotate to create rotation, anyway, more are involved in setting up "logrotate" correctly.

Due to so much trouble on setting the "logrotate" set up. I went ahead to create another branch to try out using npm package for rotation (not logrotate from Linux tool set). It is much simpler and I was able to rotate the FOM log with ECS format locally and on Openshift. I have this working branch here: "feat/331-pino-ecs--rotate-stream". If this is acceptable for MVP, then we have the log with ECS format that can be rotated and we can move on for really focusing on OpenSearch configuration. We can then cut a ticket to really improve log rotation using "logrotate" if it is preferred. @MCatherine1994 @gormless87

ianliuwk1019 commented 1 year ago

Hi @basilv : Added couple of current logged strings with ECS format (current default options implementation) for you below. Application log:

{"log.level":"info","@timestamp":"2023-07-05T19:33:39.921Z","process":{"pid":12935},"host":{"hostname":"CA-L58347M3"},"ecs":{"version":"1.6.0"},"message":"Done postStartup."}
    {
      "log.level": "info",
      "@timestamp": "2023-07-05T19:33:39.921Z",
      "process": {
        "pid": 12935
      },
      "host": {
        "hostname": "CA-L58347M3"
      },
      "ecs": {
        "version": "1.6.0"
      },
      "message": "Done postStartup."
    }
    {"log.level":"info","@timestamp":"2023-07-05T19:33:39.647Z","process":{"pid":12935},"host":{"hostname":"CA-L58347M3"},"context":"ProjectService","ecs":{"version":"1.6.0"},"message":"findPublicSummaries - Querying database with criteria '{\"includeWorkflowStateCodes\":[\"COMMENT_OPEN\",\"COMMENT_CLOSED\",\"FINALIZED\"],\"includeForestClientNumbers\":[]}'"}

    {
      "log.level": "info",
      "@timestamp": "2023-07-05T19:33:39.647Z",
      "process": {
        "pid": 12935
      },
      "host": {
        "hostname": "CA-L58347M3"
      },
      "context": "ProjectService",
      "ecs": {
        "version": "1.6.0"
      },
      "message": "findPublicSummaries - Querying database with criteria '{\"includeWorkflowStateCodes\":[\"COMMENT_OPEN\",\"COMMENT_CLOSED\",\"FINALIZED\"],\"includeForestClientNumbers\":[]}'"
    }

HTTP Request log:

In the request, you can see, it also has these information: http.request.headers.host and http.request.remoteAddress (Are these Host and Geolocation needed for Kenesis lambda arguments? So we don't need to add these in fluentbit and just let lambda taking care of them if ecs keys are correct?)

ianliuwk1019 commented 1 year ago

Just programming note: NestJs-Pino original log for http produces "req/res" for http request/response. Looking at the produced log again from using "@elastic/ecs-pino-format" with a flag "{convertReqRes: true }", it does produce needed format for http ONLY on "res" like this: "http":{"response":{"status_code":200,"headers":" . However when trying to figure out why the flag "{convertReqRes: true }" does not work for "req" (very strange), finally came across the note that states with using "pino-http" (which is the case for FOM using NestJs-pino) it is the limitation. Ref: https://www.elastic.co/guide/en/ecs-logging/nodejs/current/pino.html (see @ bottom). So it is one step closer but not sure how to solve the "req" part. (Other logger like Winston seems no such limitation stated), but probably the "req" issue could be solved in some other way.

ianliuwk1019 commented 1 year ago

Continue above programming note: Spent a day, finally can get very close to ecs format but with redundant child-json-object within the log line. Lots of experimenting, but this is probably the best we can have, due to "pino-http" has limitation with "@elastic/ecs-pino-format" flag "{convertReqRes: true }". Discover a trick with using pino option: "customSuccessObject(req, res, val)". With this to get the req/res then return them from the function itself without modifying it will make "request" object shows up in ecs "http" .object. This is the working configuration:

  const logParams: Params = {
    pinoHttp: [{
        // Note: following combination of options are probably the best I can find to 
        // produce closet ecs format log with 'pino-http'.
        // pino-http with this flag: {convertReqRes: true } has limitation for 'req'
        // see https://www.elastic.co/guide/en/ecs-logging/nodejs/current/pino.html
        // However, after many experiments, found with "customSuccessObject", 'req' will re-inserted
        // into ecs http object but still leaving original 'req' and can't be removed.
      ...ecsFormat({convertReqRes: true }), // default ecs options
      level: getLogLevel(),
      customSuccessObject(req, res, val) {
        const { responseTime } = val
        const event = {duration: responseTime} // customize 'responseTime' as ecs event.duration object.
        return { req, res, event }
      },
    },
    pino.multistream(streams)] // multistream so can have stdout & file
  }

This is the produced log: {"log.level":"info","@timestamp":"2023-07-13T06:23:11.212Z","process":{"pid":2795},"host":{"hostname":"CA-L58347M3"},"req":{"id":1,"method":"GET","url":"/api/awsCognitoConfig","query":{},"params":{"0":"awsCognitoConfig"},"headers":{"host":"localhost:3333","connection":"keep-alive","sec-ch-ua":"\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"","accept":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36","sec-ch-ua-platform":"\"Windows\"","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","accept-encoding":"gzip, deflate, br","accept-language":"en-US,en;q=0.9"},"remoteAddress":"::1","remotePort":49502},"event":{"duration":1,"id":1},"ecs":{"version":"1.6.0"},"http":{"version":"1.1","request":{"method":"GET","headers":{"host":"localhost:3333","connection":"keep-alive","sec-ch-ua":"\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"","accept":"application/json","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36","sec-ch-ua-platform":"\"Windows\"","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","accept-encoding":"gzip, deflate, br","accept-language":"en-US,en;q=0.9"}},"response":{"status_code":200,"headers":{"access-control-allow-origin":"*","content-security-policy":"default-src 'self';base-uri 'self';font-src 'self' https: data:;form-action 'self';frame-ancestors 'self';img-src 'self' data:;object-src 'none';script-src 'self';script-src-attr 'none';style-src 'self' https: 'unsafe-inline';upgrade-insecure-requests","cross-origin-embedder-policy":"require-corp","cross-origin-opener-policy":"same-origin","cross-origin-resource-policy":"same-origin","referrer-policy":"no-referrer","strict-transport-security":"max-age=15552000; includeSubDomains","x-content-type-options":"nosniff","x-dns-prefetch-control":"off","x-download-options":"noopen","x-frame-options":"SAMEORIGIN","x-permitted-cross-domain-policies":"none","x-xss-protection":"0","cache-control":"no-store, max-age=0","pragma":"no-cache","content-type":"application/json; charset=utf-8","content-length":"536","etag":"W/\"218-fYg4GM9htH267kF+zyKIFNn3+gc\""},"body":{"bytes":536}}},"url":{"full":"http://localhost:3333/api/awsCognitoConfig","path":"/api/awsCognitoConfig","domain":"localhost"},"client":{"address":"::1","ip":"::1","port":49502},"user_agent":{"original":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"},"message":"request completed"}

ianliuwk1019 commented 1 year ago

Developer's note: Matthew's reply for the log we sent: image.png

Some comments to keep you busy:

{
  "log.level": "info",
  "@timestamp": "2023-07-14T19:53:39.210Z",
  // Process fields are not enabled for most indices. Needed?
  "process": {
    "pid": 29534
  },
  "host": {
    "hostname": "CA-L58347M3"
  },
  // Fields should be in http.request.* or url.*
  "req": {
    // Unique?
    "id": 3,
    "method": "GET",
    // url.original (recommend adding domain)
    "url": "/api/project/publicSummary?includeCommentOpen=false&includePostCommentOpen=false",
    // This (and other things) can be parsed out from url.original by the lambda (urlExplode)
    "query": {
      "includeCommentOpen": "false",
      "includePostCommentOpen": "false"
    },
    "params": {
      "0": "project/publicSummary"
    },
    // Generally, we don't store headers
    // Many of these go other locations
    "headers": {
      "host": "localhost:3333",
      "connection": "keep-alive",
      "sec-ch-ua": "\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"",
      "accept": "application/json",
      "sec-ch-ua-mobile": "?0",
      "user-agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36",
      "sec-ch-ua-platform": "\"Windows\"",
      "sec-fetch-site": "same-origin",
      "sec-fetch-mode": "cors",
      "sec-fetch-dest": "empty",
      "accept-encoding": "gzip, deflate, br",
      "accept-language": "en-US,en;q=0.9"
    },
    "remoteAddress": "::1",
    "remotePort": 40960
  },
  "event": {
    "duration": 1,
    // Unique?
    "id": 3
  },
  "ecs": {
    // More like "8.8.0"
    "version": "1.6.0"
  },
  "http": {
    "version": "1.1",
    "request": {
      "method": "GET",
    // Generally, we don't store headers
    // Many of these go other locations
      "headers": {
        "host": "localhost:3333",
        "connection": "keep-alive",
        "sec-ch-ua": "\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"",
        "accept": "application/json",
        "sec-ch-ua-mobile": "?0",
        "user-agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36",
        "sec-ch-ua-platform": "\"Windows\"",
        "sec-fetch-site": "same-origin",
        "sec-fetch-mode": "cors",
        "sec-fetch-dest": "empty",
        "accept-encoding": "gzip, deflate, br",
        "accept-language": "en-US,en;q=0.9"
      }
    },
    "response": {
      "status_code": 400,
      // Generally, we don't store headers
      // Many of these go other locations
      "headers": {
        "access-control-allow-origin": "*",
        "content-security-policy": "default-src 'self';base-uri 'self';font-src 'self' https: data:;form-action 'self';frame-ancestors 'self';img-src 'self' data:;object-src 'none';script-src 'self';script-src-attr 'none';style-src 'self' https: 'unsafe-inline';upgrade-insecure-requests",
        "cross-origin-embedder-policy": "require-corp",
        "cross-origin-opener-policy": "same-origin",
        "cross-origin-resource-policy": "same-origin",
        "referrer-policy": "no-referrer",
        "strict-transport-security": "max-age=15552000; includeSubDomains",
        "x-content-type-options": "nosniff",
        "x-dns-prefetch-control": "off",
        "x-download-options": "noopen",
        "x-frame-options": "SAMEORIGIN",
        "x-permitted-cross-domain-policies": "none",
        "x-xss-protection": "0",
        "cache-control": "no-store, max-age=0",
        "pragma": "no-cache",
        "content-type": "application/json; charset=utf-8",
        "content-length": "117",
        "etag": "W/\"75-cKeXtR2e1Kl5Li3pKZ/DhlG4Z3w\""
      },
      // Just bytes
      "body": {
        "bytes": 117
      }
    }
  },
  "url": {
    // Recommned: original and the parser to explode
    "full": "http://localhost:3333/api/project/publicSummary?includeCommentOpen=false&includePostCommentOpen=false",
    "path": "/api/project/publicSummary",
    "query": "includeCommentOpen=false&includePostCommentOpen=false",
    "domain": "localhost"
  },
  "client": {
    "address": "::1",
    "ip": "::1",
    "port": 40960
  },
  "user_agent": {
    "original": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
  },
  "message": "request completed"
}
ianliuwk1019 commented 1 year ago

Additional comment after meeting with Matthew for the produced log:

TODO: add: organization.id(.name): " email recommend"

{ "log.level": "info", "@timestamp": "2023-07-14T19:53:39.210Z", // Process fields are not enabled for most indices. Needed? <Matthew mentions in OC environment running in pods, this will not usually be needed, I guess maybe due to it is not unique) "process": { "pid": 29534 }, "host": { "hostname": "CA-L58347M3" }, // Fields should be in http.request. or url. // Ian comment: Ignore this "req", it is parsed into ecf format from the library but // I am having difficulty get rid of original "req" due to library limitation. "req": { // Unique? "id": 3, "method": "GET", // url.original (recommend adding domain) "url": "/api/project/publicSummary?includeCommentOpen=false&includePostCommentOpen=false", // This (and other things) can be parsed out from url.original by the lambda (urlExplode) "query": { "includeCommentOpen": "false", "includePostCommentOpen": "false" }, "params": { "0": "project/publicSummary" }, // Generally, we don't store headers // Many of these go other locations "headers": { "host": "localhost:3333", "connection": "keep-alive", "sec-ch-ua": "\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"", "accept": "application/json", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"Windows\"", "sec-fetch-site": "same-origin", "sec-fetch-mode": "cors", "sec-fetch-dest": "empty", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9" }, "remoteAddress": "::1", "remotePort": 40960 }, "event": { "duration": 1, // Unique? "id": 3 TODO: add these: [ kind: 'event', category: 'web', dataset: 'generic.access', ] }, "ecs": { // More like "8.8.0" // TODO: [check if there is a way to change this from ecs format library used.] "version": "1.6.0" }, "http": { "version": "1.1", "request": { "method": "GET", // Generally, we don't store headers // Many of these go other locations "headers": { "host": "localhost:3333", "connection": "keep-alive", "sec-ch-ua": "\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\"", "accept": "application/json", "sec-ch-ua-mobile": "?0", "user-agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36", "sec-ch-ua-platform": "\"Windows\"", "sec-fetch-site": "same-origin", "sec-fetch-mode": "cors", "sec-fetch-dest": "empty", "accept-encoding": "gzip, deflate, br", "accept-language": "en-US,en;q=0.9" } }, "response": { "status_code": 400, // Generally, we don't store headers // Many of these go other locations "headers": { "access-control-allow-origin": "*", "content-security-policy": "default-src 'self';base-uri 'self';font-src 'self' https: data:;form-action 'self';frame-ancestors 'self';img-src 'self' data:;object-src 'none';script-src 'self';script-src-attr 'none';style-src 'self' https: 'unsafe-inline';upgrade-insecure-requests", "cross-origin-embedder-policy": "require-corp", "cross-origin-opener-policy": "same-origin", "cross-origin-resource-policy": "same-origin", "referrer-policy": "no-referrer", "strict-transport-security": "max-age=15552000; includeSubDomains", "x-content-type-options": "nosniff", "x-dns-prefetch-control": "off", "x-download-options": "noopen", "x-frame-options": "SAMEORIGIN", "x-permitted-cross-domain-policies": "none", "x-xss-protection": "0", "cache-control": "no-store, max-age=0", "pragma": "no-cache", "content-type": "application/json; charset=utf-8", "content-length": "117", "etag": "W/\"75-cKeXtR2e1Kl5Li3pKZ/DhlG4Z3w\"" }, // TODO: Just bytes. // Ian comment: However, see if changing ecs version would output differently. "body": { "bytes": 117 } } }, (url.original is sufficient) "url": { // Recommned: original and the parser to explode // TODO: Ian comment: see if changing ecs version would output differently. // Or need to use logger to change "url.full" to "url.original" "full": "http://localhost:3333/api/project/publicSummary?includeCommentOpen=false&includePostCommentOpen=false", "path": "/api/project/publicSummary", "query": "includeCommentOpen=false&includePostCommentOpen=false", "domain": "localhost" }, "client": { "address": "::1", "ip": "::1", "port": 40960 }, "user_agent": { "original": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36" }, "message": "request completed" }

ianliuwk1019 commented 1 year ago

Just leave a trace for branches information (if we need them in future):