Too much log output seems to cause processes to freeze

[john-rodewald]

Hi! We use this tool in our team to orchestrate a web application on our development machines. It's been very pleasant so far.

One of the tools in our stack managed by process-compose is Hasura. Specifically, the process is a shell script that sets environment variables and then executes graphql-engine.

For the longest time, we've observed graphql-engine occasionally freezing up for no apparent reason. A process-compose restart is enough to get it to behave again. Today I discovered something new - the problem is:

• Reliably reproducible by having graphql-engine output more logs (when running it through process-compose)
• Impossible to reproduce with a lower graphql-engine verbosity (when running it through process-compose)
• Impossible to reproduce when running graphql-engine outside of process-compose

One way that I can run graphql-engine through process-compose without any freezing is by redirecting stdout to a log file, i.e. adding 1>graphql-engine.log to the process shell script. Setting a log_location and modifying log_level in process-compose.yaml did not seem to fix freezing.

I can't say if the sheer amount of logs is what causes process-compose to choke or if something else is going on. If there exists an error log of process-compose itself or any other information that may be useful, let me know and I'll try to provide.

I'll expand this issue if I discover anything more.

[F1bonacc1]

Hi @john-rodewald,

Thank you for trying Process Compose and for letting me know about its issues.

A few questions:

1. Are you running in TUI or TUI disabled mode -t=false?
2. What version of process-compose are you using?
3. What is the log_length configured in your process-compose.yaml?
4. Not sure if your logs have ansi colors if they have, did you try processes.process_name.disable_ansi_colors: true?

Also if you'll give me some numbers, I will try to reconstruct it on my end.

1. Log lines/minute.
2. How long does it take to start freezing.

P.S.
The log_level is for process-compose internal log.
You can run process-compose info to see the process-compose log location.

[john-rodewald]

1. Are you running in TUI or TUI disabled mode -t=false?

This is in TUI mode. I've tried with -t=false with no difference in behaviour.

2. What version of process-compose are you using?

v0.45.0 at this time. The next thing I'll try is to update process-compose to v0.51.0.

3. What is the log_length configured in your process-compose.yaml?

None is configured at the moment. I now tried setting it to 10 and to 10000 with no difference in behaviour.

4. Not sure if your logs have ansi colors if they have, did you try processes.process_name.disable_ansi_colors: true?

Tried this with no difference in behaviour.

Log lines/minute.
How long does it take to start freezing.

There's a set of reproduction steps I can follow that reliably causes freezing. It seems that we're in the range of ~100 log lines per second before I see freezing. By the time I observe this peak, the process has already stopped responding.

Reducing verbosity brings me down to a peak of ~20 log lines per second. In this case, no freezing occurs.

I find these numbers to be fairly low, both in absolute and relative terms. 🤔

[F1bonacc1]

This is very helpful.
This narrows it down to a completely different place than I suspected at first. And it should be easier to address.
I will try to reconstruct it on my end and optimize the log rotation mechanism.

Another question, this one is probably more specific to your business logic. How do you measure (or experience) the freezes?

[john-rodewald]

I'm glad to hear! graphql-engine is a GraphQL server that talks to our database. This is a web application with an SPA frontend. My user story goes something like this:

• I use the application in the browser and requests succeed as expected
• Next, I follow a set of reproduction steps in a certain module
  • In this example, several entities are created and updated in quick succession, likely causing a lot of log output
• The application now becomes unresponsive (requests don't succeed anymore, content is no longer loaded)
• There is no additional log output in the TUI and all requests time out (504) until the process is restarted

We only use process-compose to help orchestrate local development environments and only ever see this problem in those local environments, never in live systems running the same GraphQL server setup.

[dzmitry-lahoda]

Seems for me this is case too.

Also reproduced - dump 5MB text file - freezes.

[F1bonacc1]

I created a small test environment that prints about 100K log lines/sec.

When it runs outside process-compose, it takes ~1.1s to print 100K lines:
I am long line number 2676253 ====================================== Duration per 100k: 0:00:01.108581

When inside process-compose, it takes ~1.3s to print 100K lines:
[bad_script_1 ] I am long line number 14839177 ====================================== Duration per 100k: 0:00:01.320320

It was running for a few minutes and was relatively stable [1.2s-1.4s] - no freezes.
With or without saving to file (process_name.log_location undefined) didn't make any difference.

Will you give this test a try on your system?

P.S.
I tested with TUI disabled: process-compose -t=false

[dzmitry-lahoda]

Not sure if that response to me) But did you tried one big 5mb or like line? not many lines, but one big?

[dzmitry-lahoda]

I guess tui may fail on such.

[F1bonacc1]

Not sure if that response to me) But did you tried one big 5mb or like line? not many lines, but one big?

I tried to cat 1GB file. OK
But when I replaced \n with in a 20MB file it didn't go so well.
Do you think it's a realistic scenario where a single line is 23040578 chars long?

Not sure that it's the same issue @john-rodewald is facing.

[dzmitry-lahoda]

20 no, but i have 5 yes. i run wasm hosts, and they sometime respond into logs with wasm blobs base64 encoded one liners.