Closed Bug 1867635 Opened 2 years ago Closed 2 years ago

Perma Updatebot all pymysql.err.OperationalError: (2003, "Can't connect to MySQL server on '127.0.0.1' ([Errno 111] Connection refused)")

Categories

(Developer Infrastructure :: Mach Vendor & Updatebot, defect, P5)

Tracking

(firefox-esr115 unaffected, firefox120 unaffected, firefox121 unaffected, firefox122 fixed)

RESOLVED FIXED
Tracking Status
firefox-esr115 --- unaffected
firefox120 --- unaffected
firefox121 --- unaffected
firefox122 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: tjr)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=438349622&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/O4SOQs_uTbSE1rjXREiQRA/runs/0/artifacts/public/logs/live_backing.log


[fetches 2023-11-30T18:06:21.931Z] fetching artifacts
[fetches 2023-11-30T18:06:21.931Z] executing ['/usr/bin/python3', '-u', '/builds/worker/checkouts/gecko/taskcluster/scripts/misc/fetch-content', 'task-artifacts']
[fetches 2023-11-30T18:06:22.001Z] attempt 1/5
[fetches 2023-11-30T18:06:22.001Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YEwFSJB0SRe1M-8JWSYZgA/artifacts/public/build/cargo-vet.tar.zst to /builds/worker/fetches/cargo-vet.tar.zst
[fetches 2023-11-30T18:06:22.001Z] attempt 1/5
[fetches 2023-11-30T18:06:22.001Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/K4AO3lFQRfiJ4DJFgYLbVQ/artifacts/public/build/rustc.tar.zst to /builds/worker/fetches/rustc.tar.zst
[fetches 2023-11-30T18:06:22.001Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YEwFSJB0SRe1M-8JWSYZgA/artifacts/public/build/cargo-vet.tar.zst
[fetches 2023-11-30T18:06:22.001Z] Downloading https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/K4AO3lFQRfiJ4DJFgYLbVQ/artifacts/public/build/rustc.tar.zst
[fetches 2023-11-30T18:06:22.001Z] /builds/worker/checkouts/gecko/taskcluster/scripts/misc/fetch-content:186: DeprecationWarning: cafile, capath and cadefault are deprecated, use a custom context instead.
[fetches 2023-11-30T18:06:22.001Z]   with urllib.request.urlopen(
[fetches 2023-11-30T18:06:22.489Z] https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YEwFSJB0SRe1M-8JWSYZgA/artifacts/public/build/cargo-vet.tar.zst resolved to 7455152 bytes with sha256 ec7bd5df63346ddf61b4291a76c545dfa07a34b1ae2fe97a4c57c76050559eb4 in 0.488s
[fetches 2023-11-30T18:06:22.489Z] Extracting /builds/worker/fetches/cargo-vet.tar.zst to /builds/worker/fetches
[fetches 2023-11-30T18:06:22.547Z] /builds/worker/fetches/cargo-vet.tar.zst extracted in 0.058s
[fetches 2023-11-30T18:06:22.547Z] Removing /builds/worker/fetches/cargo-vet.tar.zst
[fetches 2023-11-30T18:06:24.813Z] https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/K4AO3lFQRfiJ4DJFgYLbVQ/artifacts/public/build/rustc.tar.zst resolved to 300206895 bytes with sha256 5635c1154fae2ba63ebf37fa4e0ffc9123d83aa0c04b93c62203d87c4d07420f in 2.812s
[fetches 2023-11-30T18:06:24.813Z] Extracting /builds/worker/fetches/rustc.tar.zst to /builds/worker/fetches
[fetches 2023-11-30T18:06:27.202Z] /builds/worker/fetches/rustc.tar.zst extracted in 2.388s
[fetches 2023-11-30T18:06:27.202Z] Removing /builds/worker/fetches/rustc.tar.zst
[fetches 2023-11-30T18:06:27.237Z] PERFHERDER_DATA: {"framework": {"name": "build_metrics"}, "suites": [{"name": "fetch_content", "value": 5.237593171000071, "lowerIsBetter": true, "shouldAlert": false, "subtests": []}]}
[fetches 2023-11-30T18:06:27.252Z] finished fetching artifacts
[task 2023-11-30T18:06:27.253Z] executing ['bash', '-cx', '/builds/worker/run.py /builds/worker/checkouts/gecko /builds/worker/updatebot']
[task 2023-11-30T18:06:27.254Z] + /builds/worker/run.py /builds/worker/checkouts/gecko /builds/worker/updatebot
[task 2023-11-30T18:06:27.353Z] Operating mode is  prod
[task 2023-11-30T18:06:27.353Z] Getting secrets...
[task 2023-11-30T18:06:27.725Z] Setting up ssh and phab keys...
[task 2023-11-30T18:06:27.725Z] Setting up cloud_sql_proxy...
[task 2023-11-30T18:06:27.726Z] sql proxy stdout: 
[task 2023-11-30T18:06:27.726Z] sql proxy stderr: /bin/sh: 1: /builds/worker/go/bin/cloud_sql_proxy: not found
[task 2023-11-30T18:06:27.726Z] 
[task 2023-11-30T18:06:27.726Z] Getting Updatebot ready...
[task 2023-11-30T18:06:27.726Z] Writing local config file
[task 2023-11-30T18:06:27.726Z] Running updatebot
[task 2023-11-30T18:06:28.390Z] Raw _run call: ----------------------------------------------
[task 2023-11-30T18:06:28.390Z] Raw _run call: Running ['git', 'rev-parse', 'HEAD']
[task 2023-11-30T18:06:28.391Z] Raw _run call: Return: 0 Runtime (s): 0
[task 2023-11-30T18:06:28.391Z] Raw _run call: -------
[task 2023-11-30T18:06:28.391Z] Raw _run call: stdout:
[task 2023-11-30T18:06:28.391Z] Raw _run call: 22f9628eaedba1ea806dba8c7424e1ef063a708f
[task 2023-11-30T18:06:28.391Z] 
[task 2023-11-30T18:06:28.391Z] Raw _run call: -------
[task 2023-11-30T18:06:28.391Z] Raw _run call: stderr:
[task 2023-11-30T18:06:28.391Z] Raw _run call: 
[task 2023-11-30T18:06:28.391Z] Raw _run call: ----------------------------------------------
[task 2023-11-30T18:06:28.438Z] Traceback (most recent call last):
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 613, in connect
[task 2023-11-30T18:06:28.438Z]     sock = socket.create_connection(
[task 2023-11-30T18:06:28.438Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.438Z]   File "/usr/lib/python3.11/socket.py", line 851, in create_connection
[task 2023-11-30T18:06:28.438Z]     raise exceptions[0]
[task 2023-11-30T18:06:28.438Z]   File "/usr/lib/python3.11/socket.py", line 836, in create_connection
[task 2023-11-30T18:06:28.438Z]     sock.connect(sa)
[task 2023-11-30T18:06:28.438Z] ConnectionRefusedError: [Errno 111] Connection refused
[task 2023-11-30T18:06:28.438Z] 
[task 2023-11-30T18:06:28.438Z] During handling of the above exception, another exception occurred:
[task 2023-11-30T18:06:28.438Z] 
[task 2023-11-30T18:06:28.438Z] Traceback (most recent call last):
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/updatebot/./automation.py", line 117, in __init__
[task 2023-11-30T18:06:28.438Z]     'dbProvider': getOr('Database'),
[task 2023-11-30T18:06:28.438Z]                   ^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/updatebot/./automation.py", line 54, in getOr
[task 2023-11-30T18:06:28.438Z]     return _getObjOr(name)(_getConfigOr(name))
[task 2023-11-30T18:06:28.438Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/updatebot/components/dbc.py", line 15, in __init__
[task 2023-11-30T18:06:28.438Z]     self.db = MySQLDatabase(self.config)
[task 2023-11-30T18:06:28.438Z]               ^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/updatebot/components/db.py", line 154, in __init__
[task 2023-11-30T18:06:28.438Z]     self.connection = pymysql.connect(
[task 2023-11-30T18:06:28.438Z]                       ^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 353, in __init__
[task 2023-11-30T18:06:28.438Z]     self.connect()
[task 2023-11-30T18:06:28.438Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 664, in connect
[task 2023-11-30T18:06:28.438Z]     raise exc
[task 2023-11-30T18:06:28.438Z] pymysql.err.OperationalError: (2003, "Can't connect to MySQL server on '127.0.0.1' ([Errno 111] Connection refused)")
[task 2023-11-30T18:06:28.438Z] 
[task 2023-11-30T18:06:28.572Z] Traceback (most recent call last):
[task 2023-11-30T18:06:28.572Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 613, in connect
[task 2023-11-30T18:06:28.572Z]     sock = socket.create_connection(
[task 2023-11-30T18:06:28.572Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.572Z]   File "/usr/lib/python3.11/socket.py", line 851, in create_connection
[task 2023-11-30T18:06:28.572Z]     raise exceptions[0]
[task 2023-11-30T18:06:28.572Z]   File "/usr/lib/python3.11/socket.py", line 836, in create_connection
[task 2023-11-30T18:06:28.572Z]     sock.connect(sa)
[task 2023-11-30T18:06:28.572Z] ConnectionRefusedError: [Errno 111] Connection refused
[task 2023-11-30T18:06:28.572Z] 
[task 2023-11-30T18:06:28.572Z] During handling of the above exception, another exception occurred:
[task 2023-11-30T18:06:28.572Z] 
[task 2023-11-30T18:06:28.572Z] Traceback (most recent call last):
[task 2023-11-30T18:06:28.572Z]   File "/builds/worker/updatebot/./automation.py", line 323, in <module>
[task 2023-11-30T18:06:28.572Z]     u = Updatebot(localconfig)
[task 2023-11-30T18:06:28.573Z]         ^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/updatebot/./automation.py", line 140, in __init__
[task 2023-11-30T18:06:28.573Z]     raise(e)
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/updatebot/./automation.py", line 117, in __init__
[task 2023-11-30T18:06:28.573Z]     'dbProvider': getOr('Database'),
[task 2023-11-30T18:06:28.573Z]                   ^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/updatebot/./automation.py", line 54, in getOr
[task 2023-11-30T18:06:28.573Z]     return _getObjOr(name)(_getConfigOr(name))
[task 2023-11-30T18:06:28.573Z]            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/updatebot/components/dbc.py", line 15, in __init__
[task 2023-11-30T18:06:28.573Z]     self.db = MySQLDatabase(self.config)
[task 2023-11-30T18:06:28.573Z]               ^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/updatebot/components/db.py", line 154, in __init__
[task 2023-11-30T18:06:28.573Z]     self.connection = pymysql.connect(
[task 2023-11-30T18:06:28.573Z]                       ^^^^^^^^^^^^^^^^
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 353, in __init__
[task 2023-11-30T18:06:28.573Z]     self.connect()
[task 2023-11-30T18:06:28.573Z]   File "/builds/worker/.cache/pypoetry/virtualenvs/updatebot-VFmGBxYp-py3.11/lib/python3.11/site-packages/pymysql/connections.py", line 664, in connect
[task 2023-11-30T18:06:28.573Z]     raise exc
[task 2023-11-30T18:06:28.573Z] pymysql.err.OperationalError: (2003, "Can't connect to MySQL server on '127.0.0.1' ([Errno 111] Connection refused)")
[task 2023-11-30T18:06:28.702Z] Traceback (most recent call last):
[task 2023-11-30T18:06:28.702Z]   File "/builds/worker/run.py", line 219, in <module>
[task 2023-11-30T18:06:28.702Z]     subprocess.check_call(["python3", "-m", "poetry", "run", "./automation.py"])
[task 2023-11-30T18:06:28.702Z]   File "/usr/lib/python3.11/subprocess.py", line 413, in check_call
[task 2023-11-30T18:06:28.703Z]     raise CalledProcessError(retcode, cmd)
[task 2023-11-30T18:06:28.703Z] subprocess.CalledProcessError: Command '['python3', '-m', 'poetry', 'run', './automation.py']' returned non-zero exit status 1.
[taskcluster 2023-11-30 18:06:31.173Z] === Task Finished ===
[taskcluster 2023-11-30 18:06:31.174Z] Unsuccessful task run with exit code: 1 completed in 92.097 seconds

Hello Tom! Could you please take a look at this? This popped up after last merge from autoland to central, as it can be seen here.

Thank you!

Flags: needinfo?(tom)

cloud_sql_proxy is missing, which means something changed in the Docker image. I see the underlying image push-to-try was updated in Bug 1867143 so that is probably the culprit - going to look at logs...

Keywords: regression
Regressed by: 1867143

A successful log looks like:

# Build Google's Cloud SQL Proxy from source
cd /builds/worker/
+ cd /builds/worker/
mkdir cloud_sql_proxy
+ mkdir cloud_sql_proxy
cd cloud_sql_proxy
+ cd cloud_sql_proxy
go mod init cloud_sql_proxy
+ go mod init cloud_sql_proxy
go: creating new go.mod: module cloud_sql_proxy
go get github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy@$SQLPROXY_REVISION
+ go get github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy@fb1939ab92846761595833361c6b0b0ecd543861
go: downloading github.com/GoogleCloudPlatform/cloudsql-proxy v1.17.0
go: found github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy in github.com/GoogleCloudPlatform/cloudsql-proxy v1.17.0
go: downloading cloud.google.com/go v0.56.0
go: downloading google.golang.org/api v0.21.0
go: downloading golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d
go: downloading golang.org/x/net v0.0.0-20200324143707-d3edc9973b7e
go: downloading bazil.org/fuse v0.0.0-20180421153158-65cc252bf669
go: downloading google.golang.org/appengine v1.6.5
go: downloading github.com/golang/protobuf v1.4.0
go: downloading google.golang.org/protobuf v1.21.0
go: downloading google.golang.org/grpc v1.28.1
go: downloading go.opencensus.io v0.22.3
go: downloading github.com/googleapis/gax-go/v2 v2.0.5
go: downloading github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e
go: downloading google.golang.org/genproto v0.0.0-20200420144010-e5e8543f8aeb
go: downloading golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f
go: downloading golang.org/x/text v0.3.2

The log in the new images looks like:

# Build Google's Cloud SQL Proxy from source
cd /builds/worker/
+ cd /builds/worker/
mkdir cloud_sql_proxy
+ mkdir cloud_sql_proxy
cd cloud_sql_proxy
+ cd cloud_sql_proxy
go mod init cloud_sql_proxy
+ go mod init cloud_sql_proxy
go: creating new go.mod: module cloud_sql_proxy
go get github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy@$SQLPROXY_REVISION
+ go get github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy@fb1939ab92846761595833361c6b0b0ecd543861
go: downloading github.com/GoogleCloudPlatform/cloudsql-proxy v1.17.0
go: downloading cloud.google.com/go v0.56.0
go: downloading golang.org/x/net v0.0.0-20200324143707-d3edc9973b7e
go: downloading golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d
go: downloading google.golang.org/api v0.21.0
go: downloading bazil.org/fuse v0.0.0-20180421153158-65cc252bf669
go: downloading google.golang.org/appengine v1.6.5
go: downloading github.com/golang/protobuf v1.4.0
go: downloading google.golang.org/protobuf v1.21.0
go: downloading go.opencensus.io v0.22.3
go: downloading google.golang.org/grpc v1.28.1
go: downloading github.com/googleapis/gax-go/v2 v2.0.5
go: downloading github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e
go: downloading google.golang.org/genproto v0.0.0-20200420144010-e5e8543f8aeb
go: downloading golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f
go: downloading golang.org/x/text v0.3.2
go: added bazil.org/fuse v0.0.0-20180421153158-65cc252bf669
go: added cloud.google.com/go v0.56.0
go: added github.com/GoogleCloudPlatform/cloudsql-proxy v1.17.0
go: added github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e
go: added github.com/golang/protobuf v1.4.0
go: added github.com/googleapis/gax-go/v2 v2.0.5
go: added go.opencensus.io v0.22.3
go: added golang.org/x/net v0.0.0-20200324143707-d3edc9973b7e
go: added golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d
go: added golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f
go: added golang.org/x/text v0.3.2
go: added google.golang.org/api v0.21.0
go: added google.golang.org/appengine v1.6.5
go: added google.golang.org/genproto v0.0.0-20200420144010-e5e8543f8aeb
go: added google.golang.org/grpc v1.28.1
go: added google.golang.org/protobuf v1.21.0

go: found github.com/GoogleCloudPlatform/cloudsql-proxy/cmd/cloud_sql_proxy in github.com/GoogleCloudPlatform/cloudsql-proxy v1.17.0 seems to be a key difference, but I don't know why debian 12 doesn't work. I do know that this version of cloud proxy is pretty old. I'm going to try a newer one locally, then try bumping the version on holly...

Set release status flags based on info from the regressing bug 1867143

Assignee: nobody → tom
Status: NEW → ASSIGNED

Assuming that https://treeherder.mozilla.org/jobs?repo=holly&selectedTaskRun=blJYlxL6RAOIjbCg7BlMsA.0&revision=11387ee02570911f253d4020f86fe168874f1d53 works (both the docker image, and the cron job that is able to find and run the executable) this patch should fix it.

I'll be gone, but in the cron lob, you'll look for some mysql stuff a little bit after [task 2023-11-30T21:45:57.421Z] Setting up cloud_sql_proxy... that looks like this below, which is an example of it running without error:

[task 2023-11-28T17:52:15.402Z] [Debug]   MySQLDatabase: ================================================
[task 2023-11-28T17:52:15.402Z] [Info]    MySQLDatabase: Beginning MySQLDatabase.check_database
[task 2023-11-28T17:52:15.402Z] [Debug]   MySQLDatabase:  Arguments: (<components.db.MySQLDatabase object at 0x7fc9537f6940>,) {}
[task 2023-11-28T17:52:15.402Z] [Debug]   MySQLDatabase: ================================================
[task 2023-11-28T17:52:15.402Z] [Info]    MySQLDatabase: Beginning MySQLDatabase._check_and_get_configuration
[task 2023-11-28T17:52:15.402Z] [Debug]   MySQLDatabase:  Arguments: (<components.db.MySQLDatabase object at 0x7fc9537f6940>,) {}
[task 2023-11-28T17:52:15.533Z] [Debug]   MySQLDatabase: Function returned 16
[task 2023-11-28T17:52:15.533Z] [Info]    MySQLDatabase: Ending MySQLDatabase._check_and_get_configuration
[task 2023-11-28T17:52:15.533Z] [Debug]   MySQLDatabase: Function returned 16
[task 2023-11-28T17:52:15.533Z] [Info]    MySQLDatabase: Ending MySQLDatabase.check_database
Assignee: tom → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(tom)

:glandium, since you are the author of the regressor, bug 1867143, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(mh+mozilla)
Flags: needinfo?(mh+mozilla)
Assignee: nobody → tom
Status: NEW → ASSIGNED
Pushed by mh@glandium.org: https://hg.mozilla.org/integration/autoland/rev/68378d2409bc Switch to using the apt package for cloud-dql-proxy r=firefox-build-system-reviewers,glandium
Component: Networking → Mach Vendor & Updatebot
Product: Core → Developer Infrastructure
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: