Skip to content

flake: TempDir RemoveAll cleanup fails to remove temporary directories in tests occassionally #9379

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
matifali opened this issue Aug 28, 2023 · 3 comments
Closed

flake: TempDir RemoveAll cleanup fails to remove temporary directories in tests occassionally #9379

matifali opened this issue Aug 28, 2023 · 3 comments
Assignees
@Emyrk
Labels
s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks

Comments

@matifali
Copy link
Member

seen in https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370

Logs 
=== Failed
=== FAIL: enterprise/coderd TestTemplates/BlockDisablingAutoOffWithMaxTTL (0.19s)
    t.go:85: 2023-08-28 09:27:38.969 [debu]  workspaceapps.stats_collector: workspace app stats collector started
    t.go:85: 2023-08-28 09:27:38.970 [debu]  metrics_cache: deployment stats metrics refreshed  took=11.583µs  interval=5m0s
    t.go:85: 2023-08-28 09:27:38.970 [debu]  metrics_cache: template daus metrics refreshed  took=792.213µs  interval=1h0m0s
    t.go:85: 2023-08-28 09:27:38.975 [debu]  successfully subscribed to pubsub
    t.go:85: 2023-08-28 09:27:38.975 [debu]  syncing licensed entitlements
    t.go:85: 2023-08-28 09:27:38.975 [debu]  synced licensed entitlements
    t.go:85: 2023-08-28 09:27:38.975 [debu]  provisionerd: successfully connected to coderd
    t.go:85: 2023-08-28 09:27:38.982 [debu]  POST  host=localhost:62801  path=/api/v2/users/first  proto=HTTP/1.1  remote_addr=127.0.0.1  took=5.813785ms  status_code=201  latency_ms=5  request_id=6d66b114-e067-4807-a52b-9b7a4f97cfb0
    t.go:85: 2023-08-28 09:27:38.985 [debu]  POST  host=localhost:62801  path=/api/v2/users/login  proto=HTTP/1.1  remote_addr=127.0.0.1  took=1.824214ms  status_code=201  latency_ms=1  request_id=5224fba9-6c24-4fa9-8e74-1eb7f96cbf3a
    t.go:85: 2023-08-28 09:27:38.989 [debu]  POST  host=localhost:62801  path=/api/v2/licenses  proto=HTTP/1.1  remote_addr=127.0.0.1  took=3.087243ms  status_code=201  latency_ms=3  request_id=7a4eb90e-7366-421e-aa91-7a58d0294161
    t.go:85: 2023-08-28 09:27:38.989 [debu]  got pubsub update
    t.go:85: 2023-08-28 09:27:38.989 [debu]  syncing licensed entitlements
    t.go:85: 2023-08-28 09:27:38.990 [debu]  synced licensed entitlements
    t.go:85: 2023-08-28 09:27:38.992 [debu]  POST  host=localhost:62801  path=/api/v2/files  proto=HTTP/1.1  remote_addr=127.0.0.1  took=2.155254ms  status_code=201  latency_ms=2  request_id=a6f8849a-760d-48b9-867f-566542bbe827
    t.go:85: 2023-08-28 09:27:39.001 [debu]  POST  host=localhost:62801  path=/api/v2/organizations/65e97004-588e-482d-9e93-08119dd64d16/templateversions  proto=HTTP/1.1  remote_addr=127.0.0.1  took=5.086529ms  status_code=201  latency_ms=5  request_id=c4edd2ac-1dcc-41a8-9b2f-c723c931b365
    t.go:85: 2023-08-28 09:27:39.008 [debu]  POST  host=localhost:62801  path=/api/v2/organizations/65e97004-588e-482d-9e93-08119dd64d16/templates  proto=HTTP/1.1  remote_addr=127.0.0.1  took=3.64[289](https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370#step:5:290)5ms  status_code=201  latency_ms=3  request_id=9f0b98d0-0e5d-489c-805d-a42c52ce1e23
    templates_test.go:108: waiting for template version job 26404b3e-9f14-458e-b45f-e2e4bc7414ad
    t.go:85: 2023-08-28 09:27:39.026 [debu]  provisionerd-goofy_sinoussi6: locked job from database  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.029 [debu]  provisionerd: acquired job  initiator_username=testuser  provisioner=echo  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.029 [debu]  provisionerd.runner: acquired job is template import  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  user_variable_values=[]
    t.go:85: 2023-08-28 09:27:39.031 [info]  echo: unpacking template source archive  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  size_bytes=[307](https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370#step:5:308)2
    t.go:85: 2023-08-28 09:27:39.032 [debu]  echo: extracted file  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session3afc057e-f413-4ab7-a3c1-3cde47a7966a/0.parse.protobuf  mode=-rw-r--r--
    t.go:85: 2023-08-28 09:27:39.032 [debu]  echo: extracted file  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session3afc057e-f413-4ab7-a3c1-3cde47a7966a/0.apply.protobuf  mode=-rw-r--r--
    t.go:85: 2023-08-28 09:27:39.033 [debu]  echo: extracted file  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session3afc057e-f413-4ab7-a3c1-3cde47a7966a/0.plan.protobuf  mode=-rw-r--r--
    t.go:85: 2023-08-28 09:27:39.033 [debu]  echo: failed to parse readme (missing ok)  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  error="open /var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session3afc057e-f413-4ab7-a3c1-3cde47a7966a/README.md: no such file or directory"
    t.go:85: 2023-08-28 09:27:39.034 [debu]  provisionerd.runner: parse complete  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  template_variables=[]  readme_len=0  error=""
    t.go:85: 2023-08-28 09:27:39.034 [debu]  provisionerd-goofy_sinoussi6: stage UpdateJob starting  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.034 [debu]  GET  host=localhost:62801  path=/api/v2/templateversions/26404b3e-9f14-458e-b45f-e2e4bc7414ad  proto=HTTP/1.1  remote_addr=127.0.0.1  took=599.663µs  status_code=200  latency_ms=0  request_id=481c81d4-844d-4a14-984c-49e6b055226d
    t.go:85: 2023-08-28 09:27:39.035 [info]  provisionerd.runner: parse dry-run provision successful  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  resource_count=0  resources=[]
    t.go:85: 2023-08-28 09:27:39.035 [info]  provisionerd.runner: parse dry-run provision successful  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  resource_count=0  resources=[]
    t.go:85: 2023-08-28 09:27:39.035 [debu]  provisionerd-goofy_sinoussi6: stage UpdateJob starting  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.035 [debu]  provisionerd-goofy_sinoussi6: job log  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  stage="Setting up"  output=""
    t.go:85: 2023-08-28 09:27:39.036 [debu]  provisionerd-goofy_sinoussi6: job log  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  stage="Parsing template parameters"  output=""
    t.go:85: 2023-08-28 09:27:39.036 [debu]  provisionerd-goofy_sinoussi6: job log  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  stage="Detecting persistent resources"  output=""
    t.go:85: 2023-08-28 09:27:39.036 [debu]  provisionerd-goofy_sinoussi6: job log  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  stage="Detecting ephemeral resources"  output=""
    t.go:85: 2023-08-28 09:27:39.036 [debu]  provisionerd-goofy_sinoussi6: job log  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd  stage="Cleaning Up"  output=""
    t.go:85: 2023-08-28 09:27:39.037 [debu]  provisionerd-goofy_sinoussi6: inserted job logs  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.037 [debu]  provisionerd-goofy_sinoussi6: published job logs  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.037 [debu]  provisionerd.runner: sending CompletedJob  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.037 [info]  echo: recv done on Session  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a  error=EOF
    t.go:85: 2023-08-28 09:27:39.037 [debu]  echo: cleaned up work directory  session_id=3afc057e-f413-4ab7-a3c1-3cde47a7966a
    t.go:85: 2023-08-28 09:27:39.038 [debu]  provisionerd-goofy_sinoussi6: stage CompleteJob starting  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.039 [debu]  provisionerd-goofy_sinoussi6: marked import job as completed  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.039 [debu]  provisionerd-goofy_sinoussi6: stage CompleteJob done  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.039 [debu]  provisionerd.runner: sent CompletedJob  job_id=8490f747-dbea-41c3-af19-9cde2b2fb8cd
    t.go:85: 2023-08-28 09:27:39.068 [debu]  GET  host=localhost:62801  path=/api/v2/templateversions/26404b3e-9f14-458e-b45f-e2e4bc7414ad  proto=HTTP/1.1  remote_addr=127.0.0.1  took=1.52537ms  status_code=200  latency_ms=1  request_id=5f973958-c755-45eb-bbe5-ed510642ce98
    templates_test.go:108: got template version job 26404b3e-9f14-458e-b45f-e2e4bc7414ad
    t.go:85: 2023-08-28 09:27:39.085 [debu]  POST  host=localhost:62801  path=/api/v2/organizations/65e97004-588e-482d-9e93-08119dd64d16/members/me/workspaces  proto=HTTP/1.1  remote_addr=127.0.0.1  took=16.219252ms  status_code=201  latency_ms=16  request_id=1dfe2d32-84b2-40eb-84cc-05082089ad4c
    t.go:85: 2023-08-28 09:27:39.086 [debu]  PUT  host=localhost:62801  path=/api/v2/workspaces/25dcec27-[308](https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370#step:5:309)c-42e2-8858-6fc24871d76f/ttl  proto=HTTP/1.1  remote_addr=127.0.0.1  took=405.472µs  status_code=204  latency_ms=0  request_id=012f0f50-d26c-4deb-a0db-8929a99a2361
    t.go:85: 2023-08-28 09:27:39.121 [debu]  GET  host=localhost:62801  path=/api/v2/workspaces/25dcec27-308c-42e2-8858-6fc24871d76f  proto=HTTP/1.1  remote_addr=127.0.0.1  took=33.116408ms  status_code=200  latency_ms=33  request_id=0819b947-ce30-4393-bea9-2c39d1a9015a
    t.go:85: 2023-08-28 09:27:39.126 [debu]  PUT  host=localhost:62801  path=/api/v2/workspaces/25dcec27-308c-42e2-8858-6fc24871d76f/ttl  proto=HTTP/1.1  remote_addr=127.0.0.1  took=4.855137ms  status_code=204  latency_ms=4  request_id=4cdebef5-82c6-47e9-9665-4de0b82ebbc8
    t.go:85: 2023-08-28 09:27:39.128 [debu]  provisionerd-goofy_sinoussi6: locked job from database  job_id=01c05c9a-a0a3-41ed-b9fa-11ed7f3cf4b8
    t.go:85: 2023-08-28 09:27:39.142 [debu]  provisionerd: acquired job  initiator_username=testuser  provisioner=echo  job_id=01c05c9a-a0a3-41ed-b9fa-11ed7f3cf4b8  workspace_transition=START  workspace_owner=testuser  template_name=modest-dijkstra2-ghO  template_version=awesome_nash3  workspace_build_id=0566dbb9-8e25-4d97-9ce3-a66e9ee93453  workspace_id=25dcec27-308c-42e2-8858-6fc24871d76f  workspace_name=testing
    t.go:85: 2023-08-28 09:27:39.142 [debu]  provisionerd.runner: acquired job is workspace provision  job_id=01c05c9a-a0a3-41ed-b9fa-11ed7f3cf4b8  template_name=modest-dijkstra2-ghO  template_version=awesome_nash3  workspace_build_id=0566dbb9-8e25-4d97-9ce3-a66e9ee93453  workspace_id=25dcec27-308c-42e2-8858-6fc24871d76f  workspace_name=testing  workspace_owner=testuser  workspace_transition=start  workspace_name=testing  state_length=0  rich_parameter_values=[]  variable_values=[]
    t.go:85: 2023-08-28 09:27:39.142 [debu]  GET  host=localhost:62801  path=/api/v2/workspaces/25dcec27-308c-42e2-8858-6fc24871d76f  proto=HTTP/1.1  remote_addr=127.0.0.1  took=14.220677ms  status_code=200  latency_ms=14  request_id=22772350-870e-4f6b-85dc-0[318](https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370#step:5:319)e1bab908
    t.go:85: 2023-08-28 09:27:39.143 [info]  echo: unpacking template source archive  session_id=352d8e30-8cd0-4935-afa6-79810722f32f  size_bytes=3072
    t.go:85: 2023-08-28 09:27:39.143 [debu]  provisionerd-goofy_sinoussi6: stage FailJob starting  job_id=01c05c9a-a0a3-41ed-b9fa-11ed7f3cf4b8
    t.go:85: 2023-08-28 09:27:39.144 [debu]  provisionerd: closing server with error  error=<nil>
    t.go:85: 2023-08-28 09:27:39.143 [debu]  echo: extracted file  session_id=352d8e30-8cd0-4935-afa6-79810722f32f  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907[341](https://github.com/coder/coder/actions/runs/5998070538/job/16265656786?pr=9370#step:5:342)355/002/Session352d8e30-8cd0-4935-afa6-79810722f32f/0.parse.protobuf  mode=-rw-r--r--
    t.go:85: 2023-08-28 09:27:39.144 [debu]  workspaceapps.stats_collector: flushing workspace app stats
    t.go:85: 2023-08-28 09:27:39.144 [debu]  workspaceapps.stats_collector: flushed workspace app stats
    t.go:85: 2023-08-28 09:27:39.144 [debu]  workspaceapps.stats_collector: workspace app stats collector stopped
    t.go:85: 2023-08-28 09:27:39.144 [debu]  echo: extracted file  session_id=352d8e30-8cd0-4935-afa6-79810722f32f  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session352d8e30-8cd0-4935-afa6-79810722f32f/0.apply.protobuf  mode=-rw-r--r--
    testing.go:1206: TempDir RemoveAll cleanup: unlinkat /var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session352d8e30-8cd0-4935-afa6-79810722f32f: directory not empty
    t.go:85: 2023-08-28 09:27:39.145 [debu]  echo: extracted file  session_id=352d8e30-8cd0-4935-afa6-79810722f32f  size_bytes=2  path=/var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestTemplatesBlockDisablingAutoOffWithMaxTTL907341355/002/Session352d8e30-8cd0-4935-afa6-79810722f32f/0.plan.protobuf  mode=-rw-r--r--
    stuntest.go:63: STUN server shutdown

=== FAIL: enterprise/coderd TestTemplates (0.00s)
@matifali matifali added flake s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks labels Aug 28, 2023
@cdr-bot cdr-bot bot added chore labels Aug 28, 2023
@matifali matifali removed the chore label Aug 28, 2023
@matifali matifali changed the title flake: enterprise/coderd TestTemplates flake: enterprise/coderd TestTemplates/BlockDisablingAutoOffWithMaxTTL Aug 30, 2023
@deansheather
Copy link
Member

This isn't specific to this test and seems to be a general issue with CI:

testing.go:1206: TempDir RemoveAll cleanup: unlinkat /var/folders/r9/qkc3_6217d7ftqhb2465x8kh0000gn/T/TestPostTemplateByOrganizationDisableEveryone2894968490/002/Session013fb03c-1fa9-4e2b-aba3-f9ea02ceeee1: directory not empty

https://github.com/coder/coder/actions/runs/6029537206/job/16359316915?pr=9417#step:5:325

@deansheather deansheather removed their assignment Aug 30, 2023
@deansheather deansheather changed the title flake: enterprise/coderd TestTemplates/BlockDisablingAutoOffWithMaxTTL flake: TempDir RemoveAll cleanup fails to remove temporary directories in tests occassionally Aug 30, 2023
@Emyrk
Copy link
Member

Emyrk commented Sep 6, 2023

The logs in both tests have the log line

echo: extracted file  session_id=013fb03c-1fa9-4e2b-aba3-f9ea02ceeee1  size_bytes=2

very close to the error. So it seems we might be writing a file as we close, causing this error.

@Emyrk Emyrk mentioned this issue Sep 13, 2023
Merged
@Emyrk
Copy link
Member

Emyrk commented Sep 14, 2023

Please reopen if discovered again: #9668

@Emyrk Emyrk closed this as completed Sep 14, 2023
@Emyrk Emyrk mentioned this issue Sep 27, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Emyrk Emyrk

Labels
s4 Internal bugs (e.g. test flakes), extreme edge cases, and bug risks
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Emyrk @matifali @deansheather