1873752 - [traceback] TimeoutExpired: remove_orphaned_files

Status: RESOLVED FIXED

(Tecken :: General, defect, P2)

Description

[Will Kahn-Greene [:willkg] ET needinfo? me]

Sentry: https://mozilla.sentry.io/issues/4723701783/events/642158414c5b4b79a185e3e6e1f2e574/

TimeoutExpired: Command '['python', '/app/manage.py', 'remove_orphaned_files', '--skip-checks']'
timed out after 60 seconds

Looks like the remove_orphaned_files takes longer than 60 seconds semi-regularly. As of now, there are 92 events of this in the last 30 days.

Before making any changes, we should add a timing metric to learn more about how long it takes to run and how often it hits the 60 second timeout. Then we should adjust the timeout value.

Comment 1

[Daniel Thorn [:relud]]

Attachment: [mozilla-services/tecken] bug-1873752: add timing metric to remove_orphaned_files (#2879)

Comment 2

[Daniel Thorn [:relud]]

relud merged PR [mozilla-services/tecken]: bug-1873752: add timing metric to remove_orphaned_files (#2879) in 0f5b5be.

Comment 3

[Will Kahn-Greene [:willkg] ET needinfo? me]

This was deployed just now in bug #1880345 in v2024.02.14.

I verified that it's emitting data and we can see it in the "Time to remove orphaned files" panel.

Comment 4

[Daniel Thorn [:relud]]

looking at when this occurs, it appears to have mostly stopped for a while after the january 9th deploy, then it picked up again on feb 1st, and stopped again with the feb 14th deploy. So I'm going to give this a month to start happening again before taking any further action.

Comment 5

[Daniel Thorn [:relud]]

dashboard link: https://earthangel-b40313e5.influxcloud.net/d/a9-7FT0Zk/tecken-app-metrics?orgId=1&refresh=1m&var-env=prod&viewPanel=94&from=now-30d&to=now

Comment 6

[Will Kahn-Greene [:willkg] ET needinfo? me]

I tweaked that graph so it knows the values are in milliseconds and thus gives the y-axis easier to think about labels. Does that change look right?

Comment 7

[Daniel Thorn [:relud]]

that looks great! tyty

Comment 8

[Daniel Thorn [:relud]]

there have been two timeouts in the last month, so we discussed it in the obs-team meeting and we're going to double the timeout, revisit in a month, and if it didn't work double the timeout again.

Comment 9

[Bianca Danforth [:bdanforth]]

relud: Did the timeout get doubled? Another timeout error occured 2024-03-25, and it's still listing 60s as the timeout.

Edit: Interestingly, I don't see the 3 Sentry events that have occured in the last 30 days in the Grafana panel that exceeded the timeout. Everything looks to be below 55s? In the table for the graph data, the max is 53.5s.

Comment 10

[Daniel Thorn [:relud]]

i have not updated the timeout, thank you for bringing it up, I will get on that right away.

grafana not showing timeouts: correct! if i understand correctly the timeout forcibly kills the process, so the metric cannot be emitted.

Comment 11

[Daniel Thorn [:relud]]

Attachment: [mozilla-services/tecken] bug-1873752: double remove_orphaned_files timeout (#2909)

Comment 12

[Daniel Thorn [:relud]]

relud merged PR [mozilla-services/tecken]: bug-1873752: double remove_orphaned_files timeout (#2909) in b4e6880.

Comment 13

[Bianca Danforth [:bdanforth]]

Ah okay that makes sense thanks. Cool; hopefully we stop seeing those errors with the increase. It will be interesting to see how much time over 60s these runs take.

Comment 14

[Daniel Thorn [:relud]]

i archived the sentry issue "until escalating" so that we will notice that way if this issue needs to be revisited

Comment 15

[Will Kahn-Greene [:willkg] ET needinfo? me]

Timeout doubling was deployed to production just now in bug #1890798.

Comment 16

[Daniel Thorn [:relud]]

resolving this until it reappears

Comment 17

[Daniel Thorn [:relud]]

it reappeared, doubling again

Comment 18

[Daniel Thorn [:relud]]

Attachment: [mozilla-services/tecken] bug-1873752: double remove_orphaned_files timeout again (#2923)

Comment 19

[Daniel Thorn [:relud]]

marked the issue in sentry as "resolved in next release" now that we have release info

Comment 20

[Daniel Thorn [:relud]]

relud merged PR [mozilla-services/tecken]: bug-1873752: double remove_orphaned_files timeout again (#2923) in d240c52.