Constant log file activity, process spawning with no logged in users

gduprey · June 15, 2025, 11:30am

Infos:

Used Zammad version: 6.5.0-1749747762.06d0d09c.centos9
Used Zammad installation type: package
Operating system: AlmaLinux 9
Browser + version: Chrome
Using systemctl start/stop zammad to manage

Expected behavior:

Occasional log activity when app is idle/no actual logged-in users, no new websocket/server instances spawning over and over

Actual behavior:

Near constant logging activity that LOOKS like background processes are being started over and over. From the end-user perspective when you do log in, things seem to be working without issue, though there does seems to be a lot of CPU spikes/usage not correlated with any user activity

Steps to reproduce the behavior:

Start zammad, monitor production.log

You can see below, from the time stamps, that this activity is a constant stream with notices nearly every second, even though no one is logged in

tI, [2025-06-15T07:10:36.271223#3094142-6700]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.271368#3094142-6700]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.277652#3094142-6700]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.290193#3094147-6640]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.290342#3094147-6640]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.291905#3094144-6640]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.292038#3094144-6640]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.298485#3094144-6640]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.299739#3094147-6640]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.453330#3094145-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.453460#3094145-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.459455#3094150-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.459762#3094150-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.464612#3094145-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.470902#3094150-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.499828#3094143-6720]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:36.502234#3094143-6720]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:36.511868#3094143-6720]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:36.995027#3094142-6700]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:36.997987#3094147-6640]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:37.087106#3094144-6640]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:37.447908#3094145-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:37.554328#3094143-6720]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:37.618044#3094150-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:37.880136#3094147-6640]  INFO -- : Starting BackgroundServices...
I, [2025-06-15T07:10:37.880522#3094147-6640]  INFO -- : Cleanup of left over locked delayed jobs 2025-06-15 11:10:37 UTC started.
I, [2025-06-15T07:10:37.897251#3094147-6640]  INFO -- : Cleanup of left over locked delayed jobs 2025-06-15 11:10:37 UTC finished.
I, [2025-06-15T07:10:37.897335#3094147-6640]  INFO -- : Cleanup of left over import jobs 2025-06-15 11:10:37 UTC started.
I, [2025-06-15T07:10:37.898962#3094147-6640]  INFO -- : Cleanup of left over import jobs 2025-06-15 11:10:37 UTC finished.
I, [2025-06-15T07:10:37.899345#3094147-6640]  INFO -- : Skipping service ManageSessionsJobs.
I, [2025-06-15T07:10:37.899487#3094147-196060]  INFO -- : Starting thread for service ProcessDelayedJobs in the main process.
I, [2025-06-15T07:10:37.902108#3094147-196080]  INFO -- : Starting thread for service ProcessSessionsJobs in the main process.
I, [2025-06-15T07:10:37.902163#3094147-196100]  INFO -- : Starting thread for service ProcessScheduledJobs in the main process.
I, [2025-06-15T07:10:37.902513#3094147-196100]  INFO -- : ProcessScheduledJobs running...
I, [2025-06-15T07:10:37.914846#3094147-196140]  INFO -- : execute Channel.stream (try_count 0)...
I, [2025-06-15T07:10:38.914794#3094147-196200]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2025-06-15T07:10:38.916288#3094147-196200]  INFO -- : fetching imap (secure.emailsrvr.com/ticket@Schools-OPEN.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN,ssl_verify=true)
I, [2025-06-15T07:10:39.323905#3094147-196200]  INFO -- :  - no message
I, [2025-06-15T07:10:39.330502#3094147-196200]  INFO -- : ended Channel.fetch took: 0.418571363 seconds.
I, [2025-06-15T07:10:39.471591#3094150-6660]  INFO -- : Starting BackgroundServices...
I, [2025-06-15T07:10:39.472801#3094150-6660]  INFO -- : Cleanup of left over locked delayed jobs 2025-06-15 11:10:39 UTC started.
I, [2025-06-15T07:10:39.485063#3094150-6660]  INFO -- : Cleanup of left over locked delayed jobs 2025-06-15 11:10:39 UTC finished.
I, [2025-06-15T07:10:39.485147#3094150-6660]  INFO -- : Cleanup of left over import jobs 2025-06-15 11:10:39 UTC started.
I, [2025-06-15T07:10:39.486089#3094150-6660]  INFO -- : Cleanup of left over import jobs 2025-06-15 11:10:39 UTC finished.
I, [2025-06-15T07:10:39.486381#3094150-6660]  INFO -- : Skipping service ManageSessionsJobs.
I, [2025-06-15T07:10:39.486446#3094150-196080]  INFO -- : Starting thread for service ProcessDelayedJobs in the main process.
I, [2025-06-15T07:10:39.486827#3094150-196100]  INFO -- : Starting thread for service ProcessSessionsJobs in the main process.
I, [2025-06-15T07:10:39.486903#3094150-196120]  INFO -- : Starting thread for service ProcessScheduledJobs in the main process.
I, [2025-06-15T07:10:39.488997#3094150-196120]  INFO -- : ProcessScheduledJobs running...
I, [2025-06-15T07:10:40.717664#3094577-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:40.718018#3094577-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:40.730557#3094577-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:41.228831#3094612-6720]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:41.228963#3094612-6720]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:41.243390#3094612-6720]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:41.841779#3094577-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:42.138811#3094612-6720]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:45.206132#3094662-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:45.206257#3094662-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:45.217464#3094662-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:45.493717#3094689-6720]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:45.493874#3094689-6720]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:45.508571#3094689-6720]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:46.192913#3094662-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:46.574514#3094689-6720]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:49.465192#3094738-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:49.465347#3094738-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:49.479679#3094738-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:49.500439#3094150-196120]  INFO -- : ProcessScheduledJobs running...
I, [2025-06-15T07:10:49.913874#3094147-196100]  INFO -- : ProcessScheduledJobs running...
I, [2025-06-15T07:10:49.915175#3094147-196100]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2025-06-15T07:10:49.915229#3094147-196100]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2025-06-15T07:10:50.197637#3094766-6720]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:50.197787#3094766-6720]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:50.218695#3094766-6720]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:50.591493#3094738-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:51.271455#3094766-6720]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:54.209381#3094815-6660]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:54.209533#3094815-6660]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:54.222711#3094815-6660]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:54.974115#3094843-6720]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2025-06-15T07:10:54.976237#3094843-6720]  INFO -- : Using the File back end for Zammad's web socket session store.
I, [2025-06-15T07:10:54.990888#3094843-6720]  INFO -- : ActionCable is using the redis instance at redis://localhost:6379.
I, [2025-06-15T07:10:55.332011#3094815-6660]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
I, [2025-06-15T07:10:56.030392#3094843-6720]  INFO -- : ActionCable is configured to accept requests from (?-mix:https?:\/\/localhost:\d+), https://ticket.schools-open.com.
ype or paste code here

The log continues like this, issuing the same log messages about ActionCable constantly

Looking at the output of “ps”, it looks like new instances of the websocket-server keep starting and restarting (note that the PIDs are not the same for the 2nd instance of the rails server and websocket-server (these two “ps” commands where taken about 15 seconds apart)

zammad   3094141       1  0 07:10 ?        00:00:00 /bin/sleep infinity
zammad   3094142       1  1 07:10 ?        00:00:02 puma 6.6.0 (tcp://127.0.0.1:3000) [zammad]
zammad   3094144       1  1 07:10 ?        00:00:02 script/websocket-server.rb -b 127.0.0.1 -p 6042 start
zammad   3094147       1  1 07:10 ?        00:00:03 script/background-worker.rb start
zammad   3094150       1  1 07:10 ?        00:00:04 script/background-worker.rb start
postgres 3094554 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094558 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094607 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094611 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3095877 2684504  0 07:11 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3097170 2684504  0 07:12 ?        00:00:00 postgres: zammad zammad [local] idle
zammad   3099146       1 89 07:14 ?        00:00:03 script/rails server -b 127.0.0.1 -p 3000
zammad   3099186       1 95 07:14 ?        00:00:01 script/websocket-server.rb -b 127.0.0.1 -p 6042 start
postgres 3099220 2684504  0 07:14 ?        00:00:00 postgres: zammad zammad [local] SELECT

Then 10-15 seconds later

zammad   3094141       1  0 07:10 ?        00:00:00 /bin/sleep infinity
zammad   3094142       1  1 07:10 ?        00:00:02 puma 6.6.0 (tcp://127.0.0.1:3000) [zammad]
zammad   3094144       1  1 07:10 ?        00:00:02 script/websocket-server.rb -b 127.0.0.1 -p 6042 start
zammad   3094147       1  1 07:10 ?        00:00:03 script/background-worker.rb start
zammad   3094150       1  1 07:10 ?        00:00:04 script/background-worker.rb start
postgres 3094554 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094558 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094607 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3094611 2684504  0 07:10 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3095877 2684504  0 07:11 ?        00:00:00 postgres: zammad zammad [local] idle
postgres 3097170 2684504  0 07:12 ?        00:00:00 postgres: zammad zammad [local] idle
zammad   3099225       1 90 07:14 ?        00:00:02 script/rails server -b 127.0.0.1 -p 3000
postgres 3099260 2684504  7 07:14 ?        00:00:00 postgres: zammad zammad [local] idle
zammad   3099265       1 62 07:14 ?        00:00:00 script/websocket-server.rb -b 127.0.0.1 -p 6042 start

Note that the “earlier” (in each listing) PIDs are constant, but the later PIDs have changed.

It looks like the rails server and websocket server are starting 2nd instances over and over.

MrGeneration · June 15, 2025, 11:40am

Some runs background tasks permanently in the background, even without any user activity. This is expected, because you have stuff going on in the background. This is not like a PHP website that only does stuff if an user interacts.

This is absolutely necessary, I honestly don’t see an issue with that.
IDLE Zammad instances imho have a load of 0.00 to 0.01. At least in all environments I know and have.
So I must confess I do not understand if you see an issue with that or what exactly your issue is?

gduprey · June 15, 2025, 12:21pm

Thanks for the reply!

I do understand there is background activity. But this log is multiple gigabytes long after a day with no actual user activity and the system is spawning new processes constantly.

When I look over the logs, I do see the periodic events like the scheduler, escalating, etc. That is expected.

But this is repeating the stuff in the log file above (especially the ActionCable) every second and never stops. And the spawning of the additional “rails server” and “websocket-server” processes is constant. Literally dozens of new processes/instances every minute and they never stay around.

There is no one using this and this seems very distinct from the background/scheduled process.

There is “something” else going on that is driving constant process spawning for this extremely short-lived additional “rails server” and “websocket-server” processes (which is driving the constant production.log activity).

The “stable” “rails server” and “websocket-server” (earlier pids) seem ok, so it almost looks like a problem with whatever “manages” the dispatching/starting of the processes is broken

gduprey · June 15, 2025, 12:40pm

I’m actually starting to think this is something “wrong” with systemctl or the related service setup because it almost looks like systemctl cannot “see” that the rails server is running and keeps spinning up a new one, but the new one cannot work because the listener ports are already working. Same for the websocket-server service.

MrGeneration · June 15, 2025, 12:41pm

Something doesn’t add up here.
This is a low usage instance, mostly IDLE.

Is your installation really vanilla installation with info logging or did you fiddle around…?

gduprey · June 15, 2025, 12:44pm

Okay - found it. Indeed systemd/systemctl didn’t seem to think the rails/websocket server were working and so kept spawning off new instances to “restart”, but since the originals were there, the newly spawned would stop/die.

After manually starting each one and playing with the scripts, the underlying cause was a conflict with the packaged ruby 3.2.8 that was include with the packaged zammad install and the RVM ruby 3.2.8 that was already present.

When you manually ran the “rails server…” commands, things worked. When you used the “bundle”, it worked if you logged in directly, but not if you used the “/bin/bash -l -c…” wrapper (ruby had library issues).

In this case, removing the “packaged” ruby from the vendor/ directory solved the problem.

Everything fires up and runs stably and there is no longer any process spawn/excessive log activity.

gduprey · June 15, 2025, 12:46pm

It was a “standard” (non-fiddled with) install of the centos 9/almalinux package. We didn’t mess with any core/packaged files. But as I posted, the account had a conflict with an existing RVM installed ruby.

This is almost certainly us misunderstanding this as I think had we gone with a RVM ruby only (source install), all would have been OK. Or if we had used the packaged, included ruby with no RVM ruby, all would have been OK.

But clearly there was a conflict with both. Which makes sense - pick one or the other

MrGeneration · June 15, 2025, 12:49pm

Stop.
You’re actively harming your package installation.

Zammads package installation comes with a pre bundled ruby installation., You do no have to install it via RVM or any other additionally (as outlined by our documentation).

DO NOT remove the vendor directory, but remove the RVM version. Other wise you will constantly shoot yourself in the feet during updates etc.

gduprey · June 15, 2025, 12:50pm

Appreciated and I agree - cleaned up the “double ruby” problem and everything is good now!

Solution is either use the packaged install with the packaged ruby and insure you have no other ruby in the installed user context OR use the source-based install with an RVM ruby (or other install that matches), but not both.

(which may seem obvious, but…)

MrGeneration · June 15, 2025, 2:21pm

Once more, for the future anon finding this thread.
The solution for a package installation is to always use the packaged ruby binaries, not to install any further ruby packages additionally.

There’s no decision to be made for either.

system · June 22, 2025, 2:21pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.