Worker debug log?

[MarcinOrlowski]

I am facing odd issue running the SLM with Doctrine ORM, where jobs are enqueued successfully yet they seem not to execute. The worker seems to be running though as jobs are gone from the queue but their work is not done. I planted some logging into the jobs' execute() and this is not logged. Is there any approach/debug mode whatever I could try to exercise to debug this problem?

[roelvanduijnhoven]

@MarcinOrlowski Nope, I don't think there is such a thing.

What storage adapter are you using? And: can you still see your job in the queue, or is it removed after you start the worker?

Hard to help without more context!

[MarcinOrlowski]

I use DB storage and I do check that enqueued jobs are indeed correctly stored into DB. I wrote code to monitor queues and I dump the content of the queue etc. Yet, the execution seems to just do nothing and jobs are gone after that. I got all the code in execute() wrapped in try/catch + I do have exception logger as well. Nothing gets logged. This is pretty odd behavior and I suspect the culprit is something stupid, yet I am currently unable to pin it down so I am desperately checking everything possible. Any thoughts welcome.

[roelvanduijnhoven]

Weird @MarcinOrlowski! Not sure how I can help though without having some code to act on.

It is a hint too that the onboarding of this repo may be too difficult. But nothing I can do currently to remedy that.

[MarcinOrlowski]

(As there's no "Discussion" section for this repo, let me follow-up in here to avoid creating numerous tickets)

I checked query log of my deployment and noticed massive bursts of SELECTs like this (note the timestamps). Is is a bug or feature?

PHP 8.1.17 slm/queue v3.2.0 slm/queue-doctrine v4.3.0

SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:00.558742') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:01.563803') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:02.568234') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:03.573412') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:04.578224') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:05.581156') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:06.583368') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:07.586088') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:08.590090') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:09.594495') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:10.598258') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:11.602202') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:12.606020') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:13.610003') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:14.614453') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:15.617330') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:16.619447') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:17.623575') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:18.629081') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:19.631709') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:20.634583') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:21.639125') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:22.643634') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:23.646101') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:24.648581') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:25.652551') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:26.655566') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:27.658495') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:28.661206') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:29.662453') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:30.663755') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:31.665250') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:32.666461') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:33.669882') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:34.674840') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:35.679569') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:36.683865') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:37.688465') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:38.693413') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:39.696193') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:40.699759') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:41.704176') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:42.708806') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:43.713794') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:44.718463') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:45.722681') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:46.727324') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:47.732408') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:48.737389') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:48.751682') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:48.761147') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:49.765845') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:50.770040') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:51.774328') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:52.779211') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:53.784048') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:54.788517') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:55.792938') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:56.797161') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:57.801786') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:58.806592') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE
SELECT * FROM table WHERE (status = '1') AND (queue = 'name') AND (scheduled <= '2023-02-10 13:24:59.811191') ORDER BY priority ASC, scheduled ASC LIMIT 1 FOR UPDATE

[roelvanduijnhoven]

The queue is simply trying to find a new job in the database. Because you schedule jobs in the future, it queries using a timestamp (the date should be of today). Perfectly normal :heavy_check_mark: .