[Bug]: database is locked while uploading measurement

[DecFox]

A community member reported this bug while running probes:

OONI probe-cli version: 3.24.0

2025/02/18 19:30:46 Measurement URL: https://explorer.ooni.org/m/20250218233046.563312_VE_webconnectivity_2054517a8f9ad391
2025/02/18 19:30:47 	Session ID:     00001
	Query:          UPDATE "measurements" SET "measurement_file_path" = ?, "measurement_id" = ?, "measurement_is_done" = ?, "measurement_is_failed" = ?, "measurement_is_rerun" = ?, "measurement_is_upload_failed" = ?, "measurement_is_uploaded" = ?, "measurement_runtime" = ?, "measurement_start_time" = ?, "report_id" = ?, "result_id" = ?, "test_keys" = ?, "test_name" = ?, "url_id" = ? WHERE ("measurement_id" = ?)
	Arguments:      []interface {}{sql.NullString{String:"/home/vsf/.ooniprobe/msmts/websites-2025-02-18T232024.487380609Z/msmt-web_connectivity-74.json", Valid:true}, 2534, false, false, false, false, true, 0, time.Date(2025, time.February, 18, 23, 30, 43, 737384673, time.UTC), sql.NullString{String:"20250218T232233Z_webconnectivity_VE_8048_n1_3IGuuaomsYvgSzoO", Valid:true}, 573, "", "web_connectivity", sql.NullInt64{Int64:997, Valid:true}, 2534}
	Stack:          
		fmt.(*pp).handleMethods@/usr/local/go/src/fmt/print.go:673
		fmt.(*pp).printArg@/usr/local/go/src/fmt/print.go:756
		fmt.(*pp).doPrint@/usr/local/go/src/fmt/print.go:1209
		fmt.Append@/usr/local/go/src/fmt/print.go:289
		log.(*Logger).Print.func1@/usr/local/go/src/log/log.go:261
		log.(*Logger).output@/usr/local/go/src/log/log.go:238
		log.(*Logger).Print@/usr/local/go/src/log/log.go:260
		github.com/ooni/probe-cli/v3/internal/database.(*Database).UploadSucceeded@/ooni/internal/database/models.go:63
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.(*Controller).Run@/ooni/cmd/ooniprobe/internal/nettests/nettests.go:223
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.Run@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:50
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.RunGroup@/ooni/cmd/ooniprobe/internal/nettests/run.go:118
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/run.init.0.func4@/ooni/cmd/ooniprobe/internal/cli/run/run.go:67
		github.com/alecthomas/kingpin/v2.(*actionMixin).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/actions.go:28
		github.com/alecthomas/kingpin/v2.(*Application).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:568
		github.com/alecthomas/kingpin/v2.(*Application).execute@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:398
		github.com/alecthomas/kingpin/v2.(*Application).Parse@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:230
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/app.Run@/ooni/cmd/ooniprobe/internal/cli/app/app.go:14
		main.main@/ooni/cmd/ooniprobe/main.go:19
		runtime.main@/usr/local/go/src/runtime/proc.go:271
		runtime.goexit@/usr/local/go/src/runtime/asm_arm.s:859
	Rows affected:  1
	Last insert ID: 2534
	Error:          upper: slow query
	Time taken:     0.95593s
	Context:        context.Background

2025/02/18 19:30:47 	Session ID:     00001
	Query:          UPDATE "measurements" SET "measurement_file_path" = ?, "measurement_id" = ?, "measurement_is_done" = ?, "measurement_is_failed" = ?, "measurement_is_rerun" = ?, "measurement_is_upload_failed" = ?, "measurement_is_uploaded" = ?, "measurement_runtime" = ?, "measurement_start_time" = ?, "report_id" = ?, "result_id" = ?, "test_keys" = ?, "test_name" = ?, "url_id" = ? WHERE ("measurement_id" = ?)
	Arguments:      []interface {}{sql.NullString{String:"/home/vsf/.ooniprobe/msmts/websites-2025-02-18T232024.487380609Z/msmt-web_connectivity-74.json", Valid:true}, 2534, true, false, false, false, true, 3.885464911, time.Date(2025, time.February, 18, 23, 30, 43, 737384673, time.UTC), sql.NullString{String:"20250218T232233Z_webconnectivity_VE_8048_n1_3IGuuaomsYvgSzoO", Valid:true}, 573, "", "web_connectivity", sql.NullInt64{Int64:997, Valid:true}, 2534}
	Stack:          
		fmt.(*pp).handleMethods@/usr/local/go/src/fmt/print.go:673
		fmt.(*pp).printArg@/usr/local/go/src/fmt/print.go:756
		fmt.(*pp).doPrint@/usr/local/go/src/fmt/print.go:1209
		fmt.Append@/usr/local/go/src/fmt/print.go:289
		log.(*Logger).Print.func1@/usr/local/go/src/log/log.go:261
		log.(*Logger).output@/usr/local/go/src/log/log.go:238
		log.(*Logger).Print@/usr/local/go/src/log/log.go:260
		github.com/ooni/probe-cli/v3/internal/database.(*Database).Done@/ooni/internal/database/models.go:42
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.(*Controller).Run@/ooni/cmd/ooniprobe/internal/nettests/nettests.go:237
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.Run@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:50
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.RunGroup@/ooni/cmd/ooniprobe/internal/nettests/run.go:118
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/run.init.0.func4@/ooni/cmd/ooniprobe/internal/cli/run/run.go:67
		github.com/alecthomas/kingpin/v2.(*actionMixin).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/actions.go:28
		github.com/alecthomas/kingpin/v2.(*Application).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:568
		github.com/alecthomas/kingpin/v2.(*Application).execute@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:398
		github.com/alecthomas/kingpin/v2.(*Application).Parse@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:230
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/app.Run@/ooni/cmd/ooniprobe/internal/cli/app/app.go:14
		main.main@/ooni/cmd/ooniprobe/main.go:19
		runtime.main@/usr/local/go/src/runtime/proc.go:271
		runtime.goexit@/usr/local/go/src/runtime/asm_arm.s:859
	Rows affected:  1
	Last insert ID: 2534
	Error:          upper: slow query
	Time taken:     0.22025s
	Context:        context.Background

   3.47% processing input: http://www.ecequality.org/ (3h49m19.841s left)
[engine] dnslookup://www.ecequality.org...
[engine] dnslookup://www.ecequality.org... ok
[engine] using control: [{Address:https://6.th.ooni.org/ Type:https Front:} {Address:https://5.th.ooni.org/ Type:https Front:} {Address:https://d33d1gs9kpq1c5.cloudfront.net/ Type:cloudfront Front:d33d1gs9kpq1c5.cloudfront.net}]
[engine] control for http://www.ecequality.org/...
[engine] control for http://www.ecequality.org/... ok
[engine] DNS analysis result: consistent
[engine] TCP/TLS endpoints: 2/2 reachable
[engine] GET http://www.ecequality.org/...
[engine] GET http://www.ecequality.org/... ok
[engine] BodyLengthMatch: nil
[engine] BodyProportion: 0
[engine] StatusCodeMatch: true
[engine] HeadersMatch: true
[engine] TitleMatch: nil
[engine] Blocking: nil
[engine] Accessible: true
2025/02/18 19:30:54 Measurement URL: https://explorer.ooni.org/m/20250218233054.511126_VE_webconnectivity_f9b4a81349142193
2025/02/18 19:30:54 	Session ID:     00001
	Query:          UPDATE "measurements" SET "measurement_file_path" = ?, "measurement_id" = ?, "measurement_is_done" = ?, "measurement_is_failed" = ?, "measurement_is_rerun" = ?, "measurement_is_upload_failed" = ?, "measurement_is_uploaded" = ?, "measurement_runtime" = ?, "measurement_start_time" = ?, "report_id" = ?, "result_id" = ?, "test_keys" = ?, "test_name" = ?, "url_id" = ? WHERE ("measurement_id" = ?)
	Arguments:      []interface {}{sql.NullString{String:"/home/vsf/.ooniprobe/msmts/websites-2025-02-18T232024.487380609Z/msmt-web_connectivity-75.json", Valid:true}, 2535, true, false, false, false, true, 6.782839861, time.Date(2025, time.February, 18, 23, 30, 47, 948718071, time.UTC), sql.NullString{String:"20250218T232233Z_webconnectivity_VE_8048_n1_3IGuuaomsYvgSzoO", Valid:true}, 573, "", "web_connectivity", sql.NullInt64{Int64:998, Valid:true}, 2535}
	Stack:          
		fmt.(*pp).handleMethods@/usr/local/go/src/fmt/print.go:673
		fmt.(*pp).printArg@/usr/local/go/src/fmt/print.go:756
		fmt.(*pp).doPrint@/usr/local/go/src/fmt/print.go:1209
		fmt.Append@/usr/local/go/src/fmt/print.go:289
		log.(*Logger).Print.func1@/usr/local/go/src/log/log.go:261
		log.(*Logger).output@/usr/local/go/src/log/log.go:238
		log.(*Logger).Print@/usr/local/go/src/log/log.go:260
		github.com/ooni/probe-cli/v3/internal/database.(*Database).Done@/ooni/internal/database/models.go:42
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.(*Controller).Run@/ooni/cmd/ooniprobe/internal/nettests/nettests.go:237
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.Run@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:50
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.RunGroup@/ooni/cmd/ooniprobe/internal/nettests/run.go:118
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/run.init.0.func4@/ooni/cmd/ooniprobe/internal/cli/run/run.go:67
		github.com/alecthomas/kingpin/v2.(*actionMixin).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/actions.go:28
		github.com/alecthomas/kingpin/v2.(*Application).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:568
		github.com/alecthomas/kingpin/v2.(*Application).execute@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:398
		github.com/alecthomas/kingpin/v2.(*Application).Parse@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:230
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/app.Run@/ooni/cmd/ooniprobe/internal/cli/app/app.go:14
		main.main@/ooni/cmd/ooniprobe/main.go:19
		runtime.main@/usr/local/go/src/runtime/proc.go:271
		runtime.goexit@/usr/local/go/src/runtime/asm_arm.s:859
	Rows affected:  1
	Last insert ID: 2535
	Error:          upper: slow query
	Time taken:     0.23077s
	Context:        context.Background

   3.51% processing input: https://www.echr.coe.int/ (3h49m23.377s left)

[DecFox]

This also happens at the beginnning of the run:

[engine] session: using probe services: {Address:https://api.ooni.io/ Type:https Front:}
2025/02/18 20:00:02 	Session ID:     00161
	Transaction ID: 00160
	Query:          UPDATE "urls" SET "category_code" = ?, "url" = ?, "url_country_code" = ?, "url_id" = ? WHERE ("url" = ? AND "url_country_code" = ?)
	Arguments:      []interface {}{sql.NullString{String:"LGBT", Valid:true}, sql.NullString{String:"http://beyondexgay.com/", Valid:true}, sql.NullString{String:"XX", Valid:true}, sql.NullInt64{Int64:185, Valid:true}, "http://beyondexgay.com/", "XX"}
	Stack:          
		fmt.(*pp).handleMethods@/usr/local/go/src/fmt/print.go:673
		fmt.(*pp).printArg@/usr/local/go/src/fmt/print.go:756
		fmt.(*pp).doPrint@/usr/local/go/src/fmt/print.go:1209
		fmt.Append@/usr/local/go/src/fmt/print.go:289
		log.(*Logger).Print.func1@/usr/local/go/src/log/log.go:261
		log.(*Logger).output@/usr/local/go/src/log/log.go:238
		log.(*Logger).Print@/usr/local/go/src/log/log.go:260
		github.com/ooni/probe-cli/v3/internal/database.(*Database).CreateOrUpdateURL.func1@/ooni/internal/database/actions.go:339
		github.com/ooni/probe-cli/v3/internal/database.(*Database).CreateOrUpdateURL@/ooni/internal/database/actions.go:316
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.(*Controller).BuildAndSetInputIdxMap@/ooni/cmd/ooniprobe/internal/nettests/nettests.go:95
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.lookupURLs@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:33
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.Run@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:46
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.RunGroup@/ooni/cmd/ooniprobe/internal/nettests/run.go:118
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/run.init.0.func4@/ooni/cmd/ooniprobe/internal/cli/run/run.go:67
		github.com/alecthomas/kingpin/v2.(*actionMixin).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/actions.go:28
		github.com/alecthomas/kingpin/v2.(*Application).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:568
		github.com/alecthomas/kingpin/v2.(*Application).execute@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:398
		github.com/alecthomas/kingpin/v2.(*Application).Parse@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:230
	Rows affected:  1
	Last insert ID: 663
	Error:          upper: slow query
	Time taken:     0.20606s
	Context:        context.Background

2025/02/18 20:00:15 	Session ID:     00235
	Transaction ID: 00234
	Query:          UPDATE "urls" SET "category_code" = ?, "url" = ?, "url_country_code" = ?, "url_id" = ? WHERE ("url" = ? AND "url_country_code" = ?)
	Arguments:      []interface {}{sql.NullString{String:"ANON", Valid:true}, sql.NullString{String:"https://freenetproject.org/", Valid:true}, sql.NullString{String:"XX", Valid:true}, sql.NullInt64{Int64:264, Valid:true}, "https://freenetproject.org/", "XX"}
	Stack:          
		fmt.(*pp).handleMethods@/usr/local/go/src/fmt/print.go:673
		fmt.(*pp).printArg@/usr/local/go/src/fmt/print.go:756
		fmt.(*pp).doPrint@/usr/local/go/src/fmt/print.go:1209
		fmt.Append@/usr/local/go/src/fmt/print.go:289
		log.(*Logger).Print.func1@/usr/local/go/src/log/log.go:261
		log.(*Logger).output@/usr/local/go/src/log/log.go:238
		log.(*Logger).Print@/usr/local/go/src/log/log.go:260
		github.com/ooni/probe-cli/v3/internal/database.(*Database).CreateOrUpdateURL.func1@/ooni/internal/database/actions.go:339
		github.com/ooni/probe-cli/v3/internal/database.(*Database).CreateOrUpdateURL@/ooni/internal/database/actions.go:316
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.(*Controller).BuildAndSetInputIdxMap@/ooni/cmd/ooniprobe/internal/nettests/nettests.go:95
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.lookupURLs@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:33
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.WebConnectivity.Run@/ooni/cmd/ooniprobe/internal/nettests/web_connectivity.go:46
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/nettests.RunGroup@/ooni/cmd/ooniprobe/internal/nettests/run.go:118
		github.com/ooni/probe-cli/v3/cmd/ooniprobe/internal/cli/run.init.0.func4@/ooni/cmd/ooniprobe/internal/cli/run/run.go:67
		github.com/alecthomas/kingpin/v2.(*actionMixin).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/actions.go:28
		github.com/alecthomas/kingpin/v2.(*Application).applyActions@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:568
		github.com/alecthomas/kingpin/v2.(*Application).execute@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:398
		github.com/alecthomas/kingpin/v2.(*Application).Parse@/ooni/GOCACHE/oonibuild/v1/armv7/modcache/github.com/alecthomas/kingpin/v2@v2.4.0/app.go:230
	Error:          database is locked
	Time taken:     0.00028s
	Context:        context.Background

   ⨯ Failed to update the database error=database is locked
   ⨯ Failed to write to the URL table error=database is locked
   ⨯ failed to add to the URL table
   • Failed to run Websites    error=database is locked