search

superfly / fly

Deploy app servers close to your users. Package your app as a Docker image, and launch it in 17 cities with one simple CLI.
https://fly.io
985 stars 48 forks source link

Logs appearing in random order #199

Closed chilts closed 5 years ago

chilts commented 5 years ago

Here are three recent requests to the program mentioned https://github.com/superfly/fly/issues/198#issue-387960560 : https://solitary-leaf-5893.edgeapp.net/

2018-12-05T21:49:56Z syd1 [info] Putting id
2018-12-05T21:49:57Z syd1 [info] 115.189.131.28 GET https://solitary-leaf-5893.edgeapp.net/ 200 788.53ms
2018-12-05T21:49:57Z syd1 [info] Getting data
2018-12-05T21:49:57Z syd1 [info] Got data: { rand: 367 }
2018-12-05T21:49:57Z syd1 [info] Got id

2018-12-05T21:50:11Z syd1 [info] Putting id
2018-12-05T21:50:11Z syd1 [info] req=https://solitary-leaf-5893.edgeapp.net/
2018-12-05T21:50:12Z syd1 [info] 115.189.131.28 GET https://solitary-leaf-5893.edgeapp.net/ 200 787.35ms
2018-12-05T21:50:12Z syd1 [info] Got data: { rand: 760 }
2018-12-05T21:50:12Z syd1 [info] Got id
2018-12-05T21:50:12Z syd1 [info] Getting data

2018-12-05T21:50:28Z syd1 [info] Got id
2018-12-05T21:50:28Z syd1 [info] req=https://solitary-leaf-5893.edgeapp.net/
2018-12-05T21:50:28Z syd1 [info] Got data: { rand: 739 }
2018-12-05T21:50:28Z syd1 [info] Getting data
2018-12-05T21:50:28Z syd1 [info] Putting id
2018-12-05T21:50:28Z syd1 [info] 115.189.131.28 GET https://solitary-leaf-5893.edgeapp.net/ 200 792.36ms

Each request returns the console.log() statements and the server log line in different orders. Note also that the first request is missing the equivalent 2018-12-05T21:50:11Z syd1 [info] req=https://solitary-leaf-5893.edgeapp.net/ line that the next two requests have.

I know that in an evented system that messages could be re-ordered, so I guess this could be fixed in one of two ways (and I'm sure others):

  1. make sure messages are in order
  2. prepend each message with a timestamp so the messages can be re-ordered in post-processing if needed (ms won't be of sufficient granularity, but ns using process.hrtime() should work out correctly)

Thanks!

mrkurt commented 5 years ago

Oooh this'll be tricky. process.hrtime() is not free to call as often as we send off logs, but each process could keep a sequence number + timestamp and send that.

This might not get done until we get superfly/fly.rs out, but it's worth cleaning up.