search

fabiolb / fabio

Consul Load-Balancing made simple
https://fabiolb.net
MIT License
7.27k stars 616 forks source link

Logging is truncated when set to delta #792

Open scalp42 opened 4 years ago

scalp42 commented 4 years ago

When using Fabio 1.5.14 with logging set to delta, it appears that the logs are truncated:

Sep 29 23:01:43 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:01:43 [INFO] Config updates
Sep 29 23:01:43 ip-10-82-220-170 fabio[4170]: - 45.4:31201/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:01:43 ip-10-82-220-170 fabio[4170]: - route add prod-data-ranking-api /prod-data-ranking-api http://10.82.
Sep 29 23:01:59 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:01:59 [INFO] Unregistered timer _./prod-data-ranking-api
Sep 29 23:01:59 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:01:59 [INFO] Config updates
Sep 29 23:01:59 ip-10-82-220-170 fabio[4170]: - ranking-api /prod-data-ranking-api http://10.82.17.10:27041/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:01:59 ip-10-82-220-170 fabio[4170]: - route add prod-data-
Sep 29 23:02:10 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:10 [INFO] Config updates
Sep 29 23:02:10 ip-10-82-220-170 fabio[4170]: + ranking-api /prod-data-ranking-api http://10.82.45.4:31201/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:10 ip-10-82-220-170 fabio[4170]: + route add prod-data-
Sep 29 23:02:11 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:11 [INFO] Config updates
Sep 29 23:02:11 ip-10-82-220-170 fabio[4170]: + ranking-api /prod-data-ranking-api http://10.82.20.188:26312/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:11 ip-10-82-220-170 fabio[4170]: + route add prod-data-
Sep 29 23:02:37 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:37 [INFO] Config updates
Sep 29 23:02:37 ip-10-82-220-170 fabio[4170]: - ranking-api /prod-data-ranking-api http://10.82.20.188:26312/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:37 ip-10-82-220-170 fabio[4170]: - route add prod-data-
Sep 29 23:02:43 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:43 [INFO] Config updates
Sep 29 23:02:43 ip-10-82-220-170 fabio[4170]: + ranking-api /prod-data-ranking-api http://10.82.17.10:27041/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:43 ip-10-82-220-170 fabio[4170]: + route add prod-data-
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:47 [INFO] Config updates
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: + ranking-api /prod-data-ranking-api http://10.82.11.52:28403/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: + route add prod-data-
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: 2020/09/29 23:02:47 [INFO] Config updates
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: + 20.188:26312/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:02:47 ip-10-82-220-170 fabio[4170]: + route add prod-data-ranking-api /prod-data-ranking-api http://10.82.

The length restriction seems to be random, for example we get 10.82.1 here:

Sep 29 23:01:16 ip-10-82-220-170 fabio[4170]: + 7.10:27041/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:01:16 ip-10-82-220-170 fabio[4170]: + route add prod-data-ranking-api /prod-data-ranking-api http://10.82.1

Thanks in advance

scalp42 commented 4 years ago

Looking more into it, it looks like it's the full line split in reverse order:

Sep 29 23:01:43 ip-10-82-220-170 fabio[4170]: - 45.4:31201/ tags "latest" opts "strip=/prod-data-ranking-api"
Sep 29 23:01:43 ip-10-82-220-170 fabio[4170]: - route add prod-data-ranking-api /prod-data-ranking-api http://10.82.
ketzacoatl commented 2 years ago

I've also seen this in my logs from fabio. I'm assuming this is not saying that fabio has incorrect routes, and it's more of an issue buffering and writing out the log. At the very least, this makes parsing the logs impossible.

@scalp42, are you running the latest release or an older version?

Also, @scalp42, do you see this work ok if you set logging to something other than delta?

ketzacoatl commented 2 years ago

Interesting, the logs are not just truncated, they are split and in reverse order.

For example:

foobar

Is coming out like:

bar
foo

Also, it seems to happen the most on IP addresses.

ketzacoatl commented 2 years ago

One last bit, I see this on the latest stable release (v1.6.0)

scalp42 commented 2 years ago

@ketzacoatl I moved away from Fabio at this time but seems about right with what you see.

ketzacoatl commented 2 years ago

@leprechau any insights on this one? Have you seen it in your own deployments?