[Potential Bug] High CPU useage due to stuck fetch cycle

[chrishoage]

Describe the bug

Sometimes Flexo gets stuck in an update cycle that eats a ton of CPU. The logs below are abbreviated but go on for several hours.

The fall off in the image below is after i restarted the container.

I unfortunately have not figured out how to reproduce this. It hapens once every few weeks and has happened for many months now

Installation method
Docker

Distribution
default arch

Version
If you've installed Flexo from AUR, provide the output of: pacman -Qi flexo-git. If you use Docker, provide the version tag of the Docker image you're using (check docker image ls nroi/flexo for example).

Log

[2023-08-04T06:17:09.549Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-782290d3-bcca-43e3-b6e7-84b819dfce31
[2023-08-04T06:17:09.626Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:17:09.626Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:17:09.626Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:17:09.626Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:22:11.124Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:22:11.124Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:22:11.125Z INFO  flexo::mirror_flexo] File is still empty: core.db-b56ac11a-8bf0-40d5-b0b8-3fea4e1b9887
[2023-08-04T06:22:11.125Z INFO  flexo::mirror_flexo] File is still empty: extra.db-40afe6ee-cd1c-484b-a434-6f550f2b5473
[2023-08-04T06:22:11.419Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:22:11.419Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:22:11.419Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:22:11.422Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:22:11.422Z INFO  flexo::mirror_flexo] Server replied with content length 8749495 for extra/os/x86_64/extra.db
[2023-08-04T06:22:11.422Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8749495
[2023-08-04T06:22:11.732Z INFO  flexo::mirror_flexo] File size of core.db-b56ac11a-8bf0-40d5-b0b8-3fea4e1b9887 is 133624
[2023-08-04T06:22:11.732Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:22:11.745Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:22:11.746Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-0b712886-ea1f-4e6a-9c0f-131caa37e717
[2023-08-04T06:22:11.826Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:22:11.826Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:22:11.826Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:22:11.826Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:22:14.255Z INFO  flexo::mirror_flexo] File size of extra.db-40afe6ee-cd1c-484b-a434-6f550f2b5473 is 8749495
[2023-08-04T06:22:14.255Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:22:14.259Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:22:14.260Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-ac246c52-75dc-4f27-8a97-908ba3b152a1
[2023-08-04T06:22:14.342Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:22:14.342Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:22:14.342Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:22:14.342Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:27:15.828Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:27:15.828Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:27:15.829Z INFO  flexo::mirror_flexo] File is still empty: core.db-31a9a98a-61c0-4362-954b-0b7b8e7920c5
[2023-08-04T06:27:15.829Z INFO  flexo::mirror_flexo] File is still empty: extra.db-9f2aec36-2b7c-45fc-bfa1-99d104bdf14d
[2023-08-04T06:27:16.116Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:27:16.116Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:27:16.116Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:27:16.122Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:27:16.122Z INFO  flexo::mirror_flexo] Server replied with content length 8749495 for extra/os/x86_64/extra.db
[2023-08-04T06:27:16.122Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8749495
[2023-08-04T06:27:16.430Z INFO  flexo::mirror_flexo] File size of core.db-31a9a98a-61c0-4362-954b-0b7b8e7920c5 is 133624
[2023-08-04T06:27:16.431Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:27:16.449Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:27:16.449Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-868c4ef9-f731-4099-8ec9-25088cf7d463
[2023-08-04T06:27:16.531Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:27:16.531Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:27:16.531Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:27:16.531Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:27:18.968Z INFO  flexo::mirror_flexo] File size of extra.db-9f2aec36-2b7c-45fc-bfa1-99d104bdf14d is 8749495
[2023-08-04T06:27:18.968Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:27:18.974Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:27:18.975Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-2b330e2a-1f82-4595-ab8f-0475d52be1e8
[2023-08-04T06:27:19.053Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:27:19.053Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:27:19.053Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:27:19.053Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:32:20.478Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:32:20.478Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:32:20.479Z INFO  flexo::mirror_flexo] File is still empty: extra.db-547f8478-9bed-401a-9370-f4cefe10b398
[2023-08-04T06:32:20.479Z INFO  flexo::mirror_flexo] File is still empty: core.db-770d5c76-dfa8-4ce9-a0f4-8b0d5e9eb37a
[2023-08-04T06:32:20.865Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:32:20.865Z INFO  flexo::mirror_flexo] Server replied with content length 8749495 for extra/os/x86_64/extra.db
[2023-08-04T06:32:20.865Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8749495
[2023-08-04T06:32:20.871Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:32:20.871Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:32:20.871Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:32:21.193Z INFO  flexo::mirror_flexo] File size of core.db-770d5c76-dfa8-4ce9-a0f4-8b0d5e9eb37a is 133624
[2023-08-04T06:32:21.194Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:32:21.260Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:32:21.260Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-fd56debc-3fce-4b21-b471-7e22fd157336
[2023-08-04T06:32:21.341Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:32:21.341Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:32:21.341Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:32:21.341Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:32:23.609Z INFO  flexo::mirror_flexo] File size of extra.db-547f8478-9bed-401a-9370-f4cefe10b398 is 8749495
[2023-08-04T06:32:23.610Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:32:23.613Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:32:23.614Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-f0b81c8b-c555-47c6-bbfd-e3e1be22a3ce
[2023-08-04T06:32:23.707Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:32:23.707Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:32:23.707Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:32:23.708Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:37:25.131Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:37:25.131Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:37:25.131Z INFO  flexo::mirror_flexo] File is still empty: core.db-00d86d93-609b-4fd3-be06-51537236215c
[2023-08-04T06:37:25.131Z INFO  flexo::mirror_flexo] File is still empty: extra.db-b3fd1001-1cca-47dc-aad1-a4cb0076911b
[2023-08-04T06:37:25.417Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:37:25.417Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:37:25.417Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:37:25.422Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:37:25.422Z INFO  flexo::mirror_flexo] Server replied with content length 8749495 for extra/os/x86_64/extra.db
[2023-08-04T06:37:25.422Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8749495
[2023-08-04T06:37:25.731Z INFO  flexo::mirror_flexo] File size of core.db-00d86d93-609b-4fd3-be06-51537236215c is 133624
[2023-08-04T06:37:25.732Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:37:25.749Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:37:25.749Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-6986290a-b899-4f72-9a3c-6cf0668cde1c
[2023-08-04T06:37:25.832Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:37:25.832Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:37:25.832Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:37:25.832Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:37:27.988Z INFO  flexo::mirror_flexo] File size of extra.db-b3fd1001-1cca-47dc-aad1-a4cb0076911b is 8749495
[2023-08-04T06:37:27.989Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:37:27.993Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:37:27.993Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-425bf804-320f-4c5f-8cd7-9f20842790b0
[2023-08-04T06:37:28.072Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:37:28.073Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:37:28.073Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:37:28.073Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:42:29.479Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:42:29.480Z INFO  flexo::mirror_flexo] File is still empty: core.db-e90df7cf-f675-4d08-b1de-188bd4128a99
[2023-08-04T06:42:29.480Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:42:29.483Z INFO  flexo::mirror_flexo] File is still empty: extra.db-2c8e7c9b-d72b-4c57-a93f-5ffd4a5f8516
[2023-08-04T06:42:29.765Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:42:29.765Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:42:29.765Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:42:29.816Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:42:29.816Z INFO  flexo::mirror_flexo] Server replied with content length 8749495 for extra/os/x86_64/extra.db
[2023-08-04T06:42:29.816Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8749495
[2023-08-04T06:42:30.058Z INFO  flexo::mirror_flexo] File size of core.db-e90df7cf-f675-4d08-b1de-188bd4128a99 is 133624
[2023-08-04T06:42:30.059Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:42:30.070Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:42:30.071Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-f1620c2d-721e-4104-bce6-d48f6b318397
[2023-08-04T06:42:30.151Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:42:30.151Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:42:30.151Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:42:30.151Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:42:32.456Z INFO  flexo::mirror_flexo] File size of extra.db-2c8e7c9b-d72b-4c57-a93f-5ffd4a5f8516 is 8749495
[2023-08-04T06:42:32.457Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:42:32.461Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:42:32.467Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-24e0e8d1-34be-4440-a9ab-19331c3bdc27
[2023-08-04T06:42:32.545Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:42:32.545Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:42:32.545Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:42:32.545Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"
[2023-08-04T06:47:33.904Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:47:33.905Z INFO  flexo::mirror_flexo] File is still empty: core.db-60720604-2a80-4e10-9182-9cfe8efe3780
[2023-08-04T06:47:33.905Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db". Range start: 0
[2023-08-04T06:47:33.905Z INFO  flexo::mirror_flexo] File is still empty: extra.db-c333c15b-a6ce-4cc2-b4db-e09d8f017208
[2023-08-04T06:47:34.202Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:47:34.202Z INFO  flexo::mirror_flexo] Server replied with content length 133624 for core/os/x86_64/core.db
[2023-08-04T06:47:34.202Z INFO  flexo] Content length of path "core/os/x86_64/core.db" is 133624
[2023-08-04T06:47:34.205Z INFO  flexo::mirror_flexo] HTTP response code is 200
[2023-08-04T06:47:34.205Z INFO  flexo::mirror_flexo] Server replied with content length 8750657 for extra/os/x86_64/extra.db
[2023-08-04T06:47:34.205Z INFO  flexo] Content length of path "extra/os/x86_64/extra.db" is 8750657
[2023-08-04T06:47:34.527Z INFO  flexo::mirror_flexo] File size of core.db-60720604-2a80-4e10-9182-9cfe8efe3780 is 133624
[2023-08-04T06:47:34.528Z INFO  flexo] Request served [CACHE MISS]: "core/os/x86_64/core.db"
[2023-08-04T06:47:34.541Z INFO  flexo] Received request for path "core/os/x86_64/core.db.sig". Range start: 0
[2023-08-04T06:47:34.541Z INFO  flexo::mirror_flexo] File is still empty: core.db.sig-b206d929-f832-4161-8a33-0536cd0e80f3
[2023-08-04T06:47:34.623Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:47:34.623Z INFO  flexo] core/os/x86_64/core.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:47:34.623Z INFO  flexo] core/os/x86_64/core.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:47:34.623Z INFO  flexo] Request served [NO PAYLOAD]: "core/os/x86_64/core.db.sig"
[2023-08-04T06:47:43.278Z INFO  flexo::mirror_flexo] File size of extra.db-c333c15b-a6ce-4cc2-b4db-e09d8f017208 is 8750657
[2023-08-04T06:47:43.278Z INFO  flexo] Request served [CACHE MISS]: "extra/os/x86_64/extra.db"
[2023-08-04T06:47:43.282Z INFO  flexo] Received request for path "extra/os/x86_64/extra.db.sig". Range start: 0
[2023-08-04T06:47:43.283Z INFO  flexo::mirror_flexo] File is still empty: extra.db.sig-d8f0acda-59ba-4dd1-9ac0-22bf848164ef
[2023-08-04T06:47:43.361Z INFO  flexo::mirror_flexo] HTTP response code is 404
[2023-08-04T06:47:43.361Z INFO  flexo] extra/os/x86_64/extra.db.sig is not available at https://mirrors.lug.mtu.edu/archlinux/
[2023-08-04T06:47:43.361Z INFO  flexo] extra/os/x86_64/extra.db.sig was unavailable at all remote mirrors.
[2023-08-04T06:47:43.361Z INFO  flexo] Request served [NO PAYLOAD]: "extra/os/x86_64/extra.db.sig"

[nroi]

Can you please provide the flexo version you're using? (e.g. docker image ls nroi/flexo).

Also, please provide more details about how the clients are interacting with flexo, for example:

• Have you noticed any errors or something unexpected when you run pacman?
• Do you have any scripts, cronjobs or whatever that are running pacman, or otherwise interacting with flexo? Or are you certain that all requests sent to flexo are done because an actual human is running the pacman command?

I'm asking the second question because I've noticed some regularity in those log statements:

[2023-08-04T06:22:11.124Z INFO  flexo] Received request for path "core/os/x86_64/core.db".

The core.db file is the first file requested by pacman when you run pacman -Syu or pacman -Sy or similar. If you grep for those requests in the log statements, you get this:

[2023-08-04T06:22:11.124Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:27:15.828Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:32:20.478Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:37:25.131Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:42:29.479Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0
[2023-08-04T06:47:33.904Z INFO  flexo] Received request for path "core/os/x86_64/core.db". Range start: 0

If you compare the timestamps, they are all 5 minutes and about 4.5 seconds apart. Even though I cannot rule out that this is caused by a flexo bug, I just want to ask if you have a cron job or something before I start chasing ghosts 😉

[chrishoage]

Can you please provide the flexo version you're using? (e.g. docker image ls nroi/flexo).

❯ docker image ls nroi/flexo
REPOSITORY   TAG       IMAGE ID       CREATED         SIZE
nroi/flexo   latest    6609a4785656   5 days ago      112MB
nroi/flexo   <none>    601652172d6e   10 months ago   112MB

Have you noticed any errors or something unexpected when you run pacman?
Do you have any scripts, cronjobs or whatever that are running pacman, or otherwise interacting with flexo? Or are you certain that all requests sent to flexo are done because an actual human is running the pacman command?

I have a polybar script which runs checkupdates every 5 minutes to check to see if there are any pending updates.

The logs may be a red herring in this case. The eating a lot of CPU until it restarts happens maybe once a month or so?

It doesn't "go away" and even happens when the system that runs checkupdates is asleep and not hitting the flexo mirror for updates. In my screenshot above for example in my screenshot above no computer on my network was asking for updates every 5 minutes.

So perhaps the logs are not showing what is eating the CPU.

I didn't have the presence of mind to inspect the container to see what process was eating CPU (I restarted the container from bed with my phone since I could hear my server was working hard for no reason 😅) - next time this happens I will do so to provide additional information.

[nroi]

I didn't have the presence of mind to inspect the container to see what process was eating CPU

Alright. If it's not too much effort, and you have no concerns regarding privacy, please also provide a coredump (I don't expect any privacy-relevant data in the flexo coredump, but that's up to you). You can send it to me via e-mail: nroi@mailbox.org

Here's how to create a coredump on flexo running via docker:

• docker exec -it <container-id> /bin/bash
• then, inside the docker container, kill the process via: kill -11 $(pidof flexo).
• the coredump is then on the host system inside the /var/lib/systemd/coredump directory (if you're running ArchLinux).

[nroi]

Also, if you have any logs available from the time when the CPU load was so high, that would also be helpful.

[chrishoage]

Unfortunately it looks like the logs rotated out and I'm having difficulty with coredump (running an ubuntu host at the moment)

This happens with some frequency so next time it does I will immediately gather logs and investigate how to generate a core dump when I have more time to dedicate to debugging this

In the mean time leaving this open may help gather information if anyone else has similar behavior (or not - which would indicate this is something broken with my setup)

Thank you for your help!

[Kokan]

I also saw high cpu usage from time to time. Restarting flexo always helps, as it runs in a VM I have created a snapshoot with memory when it is in high cpu usage state so possible I can revert back to that version if needed. Also collected the followings:

• strace output
• logs from flexo
• core dump

I can share those information privately (specially the core dump)

--Type <RET> for more, q to quit, c to continue without paging--
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `/usr/bin/flexo'.
#0  0x00007be3e6b54be2 in ?? () from /usr/lib/libc.so.6
[Current thread is 1 (Thread 0x7be3e5f90840 (LWP 286115))]
(gdb) info thread
  Id   Target Id                          Frame
* 1    Thread 0x7be3e5f90840 (LWP 286115) 0x00007be3e6b54be2 in ?? () from /usr/lib/libc.so.6
  2    Thread 0x7be3a05eb6c0 (LWP 294943) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  3    Thread 0x7be3e44bb6c0 (LWP 292808) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  4    Thread 0x7be395fc86c0 (LWP 292234) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  5    Thread 0x7be3963ca6c0 (LWP 292233) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  6    Thread 0x7be3cc5f16c0 (LWP 292219) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  7    Thread 0x7be39e5ea6c0 (LWP 292218) 0x0000582da928a7f8 in ?? ()
  8    Thread 0x7be3e4b646c0 (LWP 291887) 0x0000582da90d9913 in ?? ()
  9    Thread 0x7be3e4d656c0 (LWP 291886) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  10   Thread 0x7be3e4f666c0 (LWP 291885) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  11   Thread 0x7be3e5cf56c0 (LWP 291884) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  12   Thread 0x7be3a3bfd6c0 (LWP 291883) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  13   Thread 0x7be3ccdf26c0 (LWP 291882) 0x00007be3e6b68c70 in memcpy () from /usr/lib/libc.so.6
  14   Thread 0x7be3ce3f76c0 (LWP 291881) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  15   Thread 0x7be3cc3f06c0 (LWP 291880) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  16   Thread 0x7be3cf1fb6c0 (LWP 291879) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  17   Thread 0x7be3a13f26c0 (LWP 291819) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  18   Thread 0x7be3a15f36c0 (LWP 291818) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  19   Thread 0x7be3a19f56c0 (LWP 291816) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  20   Thread 0x7be3a1bf66c0 (LWP 291815) 0x0000582da928a7f8 in ?? ()
  21   Thread 0x7be3a27f96c0 (LWP 291814) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  22   Thread 0x7be39bbdb6c0 (LWP 291813) 0x00007be3e6bc3ed6 in statx () from /usr/lib/libc.so.6
  23   Thread 0x7be3e51676c0 (LWP 291750) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  24   Thread 0x7be3e53686c0 (LWP 291749) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  25   Thread 0x7be3e55696c0 (LWP 291748) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  26   Thread 0x7be3e576a6c0 (LWP 291747) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  27   Thread 0x7be3e596b6c0 (LWP 291746) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  28   Thread 0x7be3e5efc6c0 (LWP 291745) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  29   Thread 0x7be39d3e16c0 (LWP 291683) 0x00007be3e6bc3ece in statx () from /usr/lib/libc.so.6
  30   Thread 0x7be39d5e26c0 (LWP 291682) 0x0000582da928a88d in ?? ()

The strace mainly contains call to statx(this is a result of a few seconds of attached strace):

sort flexo.291682 |uniq -c
  30088 statx(4, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=638448, ...}) = 0

[FixedWing99]

I can confirm the report.

top - 10:57:24 up 7 days, 25 min, 1 user, load average: 1.00, 1.00, 1.00
Threads: 2 total, 1 running, 1 sleep, 0 d-sleep, 0 stopped, 0 zombie
%Cpu(s): 13.6 us, 11.2 sy, 0.0 ni, 75.0 id, 0.0 wa, 0.2 hi, 0.0 si, 0.0 st
MiB Mem : 3800.0 total, 878.2 free, 706.2 used, 2503.7 buff/cache
MiB Swap: 2048.0 total, 2048.0 free, 0.0 used. 3093.8 avail Mem

PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND

64155 flexo 20 0 984196 41104 12652 R 99.2 1.1 95:27.54 flexo
60551 flexo 20 0 984196 41104 12652 S 0.0 1.1 0:03.99 flexo

[root@SCGZ sjw]# pacman -Qi flexo
Name : flexo
Version : 1.6.10-1
Description : A central pacman cache
Architecture : x86_64
URL : https://github.com/nroi/flexo
Licenses : MIT
Groups : None
Provides : flexo
Depends On : curl pacman-contrib
Optional Deps : None
Required By : None
Optional For : None
Conflicts With : flexo-git
Replaces : None
Installed Size : 3.45 MiB
Packager : Unknown Packager
Build Date : Sun 27 Apr 2025 12:51:19 PM EDT
Install Date : Sun 27 Apr 2025 01:10:46 PM EDT
Install Reason : Explicitly installed
Install Script : No
Validated By : None

[root@SCGZ sjw]#

For me, it will run for hours and hours like that, fully consuming one CPU.

[root@SCGZ sjw]# strace -p 60551
strace: Process 60551 attached
accept4(3

[root@SCGZ sjw]# strace -p 64155
...
statx(11, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=23803259, ...}) = 0
statx(11, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=23803259, ...}) = 0
strace: Process 64155 detached
[root@SCGZ sjw]#

[root@SCGZ sjw]# ls -l /proc/64155/fd
total 0
lr-x------ 1 flexo flexo 64 Mar 14 11:14 0 -> /dev/null
lrwx------ 1 flexo flexo 64 Mar 14 11:14 1 -> 'socket:[151358]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 10 -> 'anon_inode:[eventfd]'
lr-x------ 1 flexo flexo 64 Mar 14 11:14 11 -> /var/cache/flexo/pkg/extra/os/x86_64/llvm-22.1.1-1-x86_64.pkg.tar.zst
lrwx------ 1 flexo flexo 64 Mar 14 11:14 12 -> 'anon_inode:[eventfd]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 16 -> 'anon_inode:[eventfd]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 17 -> 'socket:[166764]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 18 -> 'anon_inode:[eventfd]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 2 -> 'socket:[151358]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 25 -> 'anon_inode:[eventfd]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 3 -> 'socket:[155914]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 4 -> 'socket:[167520]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 7 -> 'anon_inode:[eventfd]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 8 -> 'socket:[167725]'
lrwx------ 1 flexo flexo 64 Mar 14 11:14 9 -> 'socket:[166734]'
[root@SCGZ sjw]#

On my systems, one machine failed to fully download llvm-22.1.1-1-x86_64.pkg.tar.zst and gave up, leaving a partial/corrupted file locally. Another machine then successfully downloaded and installed it, which indicates the file in the Flexo cache is not corrupted and the loop is not caused by an actual corrupt package, but by Flexo’s repeated stat/poll logic on that path.

If I restart, Flexo will run fine, but then soon return to this state.

Stephen