/rest/v3/short-urls?page=1&orderBy=dateCreated-DESC returning 500 error

[axsuul]

Shlink version

v3.6.3

PHP version

N/A

How do you serve Shlink

Other (explain in summary)

Database engine

PostgreSQL

Database version

12

Summary

Hi, I'm using this Docker image. I have already tried the roadrunner variant as well.

I'm getting 90% 500 errors when loading recent short URLs. In the browser console, it's this request path that's returning the 500: /rest/v3/short-urls?page=1&orderBy=dateCreated-DESC. If I refresh the page enough sometimes I will get it to load. Other requests seem to succeed just fine.

The logs don't seem to reveal anything as to why it's returning a 500 error.

2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 40, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 35, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 39, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 38, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 36, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 41, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 37, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 42, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 47, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 53, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 48, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 54, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 57, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 58, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 56, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:28:53+0000	DEBUG	server      	worker is allocated	{"pid": 59, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:29:07+0000	INFO	server      	[2023-08-25T14:29:07.931727+00:00] [d3ffa8cf-0f09-4c02-a306-42865c5dde31] Access.INFO - GET /rest/v3/health 200 120
2023-08-25T14:29:08+0000	INFO	server      	[2023-08-25T14:29:08.032571+00:00] [9258482f-1da0-4e36-9b97-2bc43e7af0a2] Shlink.WARNING - This Shlink instance is not integrated with a mercure hub.

2023-08-25T14:29:08+0000	INFO	server      	[2023-08-25T14:29:08.032978+00:00] [9258482f-1da0-4e36-9b97-2bc43e7af0a2] Access.INFO - GET /rest/v3/mercure-info 501 189
2023-08-25T14:29:08+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T14:29:08+0000	DEBUG	server      	worker is allocated	{"pid": 65, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:29:08+0000	INFO	server      	[2023-08-25T14:29:08.256335+00:00] [fd0c835c-7b25-430d-a295-0bbe4b588ee4] Access.INFO - GET /rest/v3/short-urls?page=1&orderBy=dateCreated-DESC 200 6260
2023-08-25T14:29:08+0000	INFO	server      	[2023-08-25T14:29:08.730241+00:00] [97724a44-96e0-47b9-a1f8-f54e9a3ce17c] Access.INFO - GET /rest/v3/tags/stats 200 233
2023-08-25T14:29:14+0000	INFO	server      	[2023-08-25T14:29:14.755961+00:00] [80c59266-2ad6-4688-859a-b2378981c42d] Access.INFO - GET /rest/v3/health 200 120
2023-08-25T14:29:14+0000	INFO	server      	[2023-08-25T14:29:14.841133+00:00] [1784ec71-5cdd-44ad-800e-3ebdedbaa94c] Shlink.WARNING - This Shlink instance is not integrated with a mercure hub.

2023-08-25T14:29:14+0000	INFO	server      	[2023-08-25T14:29:14.841441+00:00] [1784ec71-5cdd-44ad-800e-3ebdedbaa94c] Access.INFO - GET /rest/v3/mercure-info 501 189
2023-08-25T14:29:14+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T14:29:14+0000	WARN	server      	network error	{"reason": "network", "pid": 41, "internal_event_name": "EventWorkerError", "error": "worker_exec: Network:\n\tsync_worker_exec_payload: EOF"}
2023-08-25T14:29:14+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T14:29:14+0000	DEBUG	server      	worker is allocated	{"pid": 66, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:29:15+0000	DEBUG	server      	worker is allocated	{"pid": 67, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T14:29:15+0000	INFO	server      	[2023-08-25T14:29:15.549395+00:00] [9b00530d-abf7-4d01-8517-ebd981e9b1fa] Access.INFO - GET /rest/v3/tags/stats 200 233

Any suggestions on how to debug this? Thanks for the software.

[acelaya]

Can you check the browser console and share the response payload for those 500 errors?

Are you using any kind of reverse proxy? Where do you deploy/how do you run the docker container?

Usually, exceptions on Shlink would be logged. If nothing shows on the logs, I suspect something else is failing between the browser and Shlink.

[axsuul]

There seems to be no response payload (Chrome).

Yep I'm using Traefik but also not seeing anything in the logs there. I run the Docker container using HashiCorp Nomad. I've also noticed every 10 or so refreshes the /rest/v3/health endpoint will also return a 500.

Actually, looking closer into the logs, it seems these are the errors that are probably related to the 500 errors from /rest/v3/short-urls?page=1&orderBy=dateCreated-DESC returning 500 error

network error	{"reason": "network", "pid": 74, "internal_event_name": "EventWorkerError", "error": "worker_exec: Network:\n\tsync_worker_exec_payload: EOF"}
2023-08-25T15:57:50+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T15:57:51+0000	DEBUG	server      	worker is allocated	{"pid": 76, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T15:57:51+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T15:57:51+0000	DEBUG	server      	worker is allocated	{"pid": 77, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T15:57:51+0000	DEBUG	server      	worker is allocated	{"pid": 78, "internal_event_name": "EventWorkerConstruct"}

and these errors seem to coincide with /rest/v3/health returning 500

etwork error	{"reason": "network", "pid": 77, "internal_event_name": "EventWorkerError", "error": "worker_exec: Network:\n\tsync_worker_exec_payload: EOF"}
2023-08-25T15:58:07+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T15:58:07+0000	DEBUG	server      	worker is allocated	{"pid": 85, "internal_event_name": "EventWorkerConstruct"}
2023-08-25T15:58:07+0000	WARN	server      	network error	{"reason": "network", "pid": 37, "internal_event_name": "EventWorkerError", "error": "worker_exec: Network:\n\tsync_worker_exec_payload: EOF"}
2023-08-25T15:58:07+0000	DEBUG	server      	worker stopped	{"internal_event_name": "EventWorkerWaitExit", "error": "signal: killed\nprocess_wait: signal: killed"}
2023-08-25T15:58:07+0000	DEBUG	server      	worker is allocated	{"pid": 86, "internal_event_name": "EventWorkerConstruct"}

Does that help?

[acelaya]

Those are roadrunner logs (the daemon that serves Shlink on the docker image).

Workers are the processes that handle HTTP requests and jobs. If they get killed, roadrunner spans new workers, but it seems as if there was something on your environment which is killing them, or maybe they run out of "resources?" and get replaced by new ones, or communication between roadrunner's main process and workers fails.

I have searched on their issues for some of those errors. There are references in old closed issues, but nothing seems particularly relevant I'm afraid:

• https://github.com/roadrunner-server/roadrunner/issues?q=is%3Aissue+process_wait%3A+signal%3A+killed+is%3Aclosed
• https://github.com/roadrunner-server/roadrunner/issues?q=is%3Aissue+sync_worker_exec_payload+is%3Aclosed

[axsuul]

Ah that was it! I gave it more resources (256 MB → 1 GB) and the error went away. Thanks 😅

[axsuul]

Well actually, maybe that was a premature reply. I gave it 2 GB now and it's better but it still responds with 500 every now and then. Any other ideas?

[acelaya]

Try with less workers.

By default it infers that from the amount of available cores. Perhaps it's detecting a large number of cores in the host machine, while the amount of memory is not enough for all of them. Every worker will try to reserve some memory.

Try with, let's say WEB_WORKER_NUM=10 and TASK_WORKER_NUM=10 https://shlink.io/documentation/environment-variables/#server

[axsuul]

Alright looks like I was able to resolve it by giving Postgres extra memory too. Closing for now, thanks again.

[acelaya]

I usually keep discussions open, and mark a successful answer instead.