abra app logs does not show log entries in correct chronological order #416

New Issue

2023-02-13T13:28:58Z

yksflip commented

2023-02-13 13:28:58 +00:00

Don't know how this happens, but I saw this already quite some times using abra app logs. Maybe another dead container that shows up here? Would be super helpful for debugging stuff to have this in order :)

(Also not sure if bug or feature request? :D)

An example:

$ abra app logs monitoring.dev.local-it.cloud loki 
2023-02-13T13:22:31.490617293Z level=info ts=2023-02-13T13:22:31.490543633Z caller=table_manager.go:476 msg="creating table" table=index_2629

# This one seems to be wrong here ...
2023-02-13T12:13:46.392724417Z level=error ts=2023-02-13T12:13:46.39204293Z caller=main.go:85 msg="validating config" err="invalid schema config: must specify at least one schema configuration"

2023-02-13T13:22:31.490690194Z level=info ts=2023-02-13T13:22:31.490615957Z caller=table_manager.go:476 msg="creating table" table=index_2659
[...]
2023-02-13T13:22:31.491993274Z level=info ts=2023-02-13T13:22:31.491778297Z caller=table_manager.go:476 msg="creating table" table=index_2716

# This one seems to be wrong here ...
2023-02-13T12:13:37.479073390Z level=error ts=2023-02-13T12:13:37.477998446Z caller=main.go:85 msg="validating config" err="invalid schema config: must specify at least one schema configuration"

2023-02-13T13:24:31.428684703Z level=info ts=2023-02-13T13:24:31.427754158Z caller=table_manager.go:324 msg="synching tables" expected_tables=144

edit: make example more clear

Don't know how this happens, but I saw this already quite some times using abra app logs. Maybe another dead container that shows up here? Would be super helpful for debugging stuff to have this in order :) (Also not sure if bug or feature request? :D) An example: ```bash $ abra app logs monitoring.dev.local-it.cloud loki 2023-02-13T13:22:31.490617293Z level=info ts=2023-02-13T13:22:31.490543633Z caller=table_manager.go:476 msg="creating table" table=index_2629 # This one seems to be wrong here ... 2023-02-13T12:13:46.392724417Z level=error ts=2023-02-13T12:13:46.39204293Z caller=main.go:85 msg="validating config" err="invalid schema config: must specify at least one schema configuration" 2023-02-13T13:22:31.490690194Z level=info ts=2023-02-13T13:22:31.490615957Z caller=table_manager.go:476 msg="creating table" table=index_2659 [...] 2023-02-13T13:22:31.491993274Z level=info ts=2023-02-13T13:22:31.491778297Z caller=table_manager.go:476 msg="creating table" table=index_2716 # This one seems to be wrong here ... 2023-02-13T12:13:37.479073390Z level=error ts=2023-02-13T12:13:37.477998446Z caller=main.go:85 msg="validating config" err="invalid schema config: must specify at least one schema configuration" 2023-02-13T13:24:31.428684703Z level=info ts=2023-02-13T13:24:31.427754158Z caller=table_manager.go:324 msg="synching tables" expected_tables=144 ``` edit: make example more clear

yksflip added the bug label 2023-02-13 13:28:59 +00:00

decentral1se commented

2023-02-13 14:38:42 +00:00

@yksflip

Righhht, so, for context, there was no "off the shelf" API for "give me all the logs", so I had to cook up a concurrent "stream everything you can from every service and merge them into a single stdout/stderr stream" which is abra app logs today 🙃

Are we specifically speaking about out of order timestamps here? I think that is probably just a bug. I think I see out of order timestamps at least, in the millisecs?

Or are we talking about somehow stream all logs from all services but then "mixing" them in a less chaotic manner?

@yksflip Righhht, so, for context, there was no "off the shelf" API for "give me all the logs", so I had to cook up a concurrent "stream everything you can from every service and merge them into a single stdout/stderr stream" which is `abra app logs` today 🙃 Are we specifically speaking about out of order timestamps here? I think that is probably just a bug. I think I see out of order timestamps at least, in the millisecs? Or are we talking about somehow stream all logs from all services but then "mixing" them in a less chaotic manner?

decentral1se commented

2023-02-13 14:42:15 +00:00

It could be that the logs from the services that appear to have out of order timestamps are just streaming in at weird times due to things like network or service latency...

yksflip commented

2023-02-13 14:51:01 +00:00

ah okayy, I think I get it now ... I think what happened was:

deploy a broken service
fix the config
deploy fixed service
abra app logs
still see the logs of the broken service mixed in (almost 1h difference)

but yeah maybe thats just good enough for now and better logging are part of the monitoring stack :D

ah okayy, I think I get it now ... I think what happened was: 1. deploy a broken service 2. fix the config 3. deploy fixed service 4. abra app logs still see the logs of the broken service mixed in (almost 1h difference) but yeah maybe thats just good enough for now and better logging are part of the monitoring stack :D

🎉 1

decentral1se commented

2023-02-13 15:53:29 +00:00

Aha, I see. Perhaps we could make an improvement here. I see that there is a Since option we're not making use of but could? Maybe this could be configured from the CLI? See https://pkg.go.dev/github.com/docker/docker@v23.0.1+incompatible/api/types#ContainerLogsOptions for the options. See eec6469ba1/cli/app/logs.go (L22) for options we do set.

Aha, I see. Perhaps we could make an improvement here. I see that there is a `Since` option we're not making use of but could? Maybe this could be configured from the CLI? See https://pkg.go.dev/github.com/docker/docker@v23.0.1+incompatible/api/types#ContainerLogsOptions for the options. See https://git.coopcloud.tech/coop-cloud/abra/src/commit/eec6469ba1cbae45f70e8172651fd139e5344df6/cli/app/logs.go#L22 for options we do set.

yksflip referenced this issue from toolshed/abra

2023-02-13 23:25:02 +00:00

feat: adds --since flag for abra app logs #276

yksflip commented

2023-02-13 23:28:00 +00:00