Skip to content
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions cumulusci/cli/org.py
Original file line number Diff line number Diff line change
Expand Up @@ -134,6 +134,7 @@ def setup_client(connected_app, login_url=None, sandbox=None) -> OAuth2Client:
auth_uri=f"{base_uri}/services/oauth2/authorize",
token_uri=f"{base_uri}/services/oauth2/token",
scope="web full refresh_token",
pkce=True,
)
return OAuth2Client(sf_client_config)

Expand Down
90 changes: 83 additions & 7 deletions cumulusci/core/config/org_config.py
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
import os
import re
from collections import defaultdict, namedtuple
from contextlib import contextmanager
from contextlib import contextmanager, nullcontext
from datetime import date, datetime
from typing import Optional
from urllib.parse import urlparse
Expand All @@ -14,9 +14,11 @@
from cumulusci.core.exceptions import (
CumulusCIException,
DependencyResolutionError,
OrgNotFound,
ServiceNotConfigured,
)
from cumulusci.oauth.client import OAuth2Client, OAuth2ClientConfig
from cumulusci.oauth.exceptions import OAuth2Error
from cumulusci.oauth.salesforce import SANDBOX_LOGIN_URL, jwt_session
from cumulusci.utils import parse_api_datetime
from cumulusci.utils.fileutils import open_fs_resource
Expand Down Expand Up @@ -60,6 +62,7 @@ class OrgConfig(BaseConfig):
default: bool
client_id: str
refresh_token: str
refresh_token_rotation: bool
client_secret: str
connected_app: str
serialization_format: str
Expand Down Expand Up @@ -90,7 +93,10 @@ def refresh_oauth_token(self, keychain, connected_app=None, is_sandbox=False):
this is done using the Oauth2 JWT flow.

Otherwise it is done using the Oauth2 Refresh Token flow using the connected app
configured in the keychain's connected_app service.
configured in the keychain's connected_app service. If the connected app uses
refresh token rotation, the stored access token is reused while it still works,
and a new refresh token is saved to the keychain right away, because the old one
no longer works.

Also refreshes user and org info that is cached in the org config.
"""
Expand All @@ -107,13 +113,67 @@ def refresh_oauth_token(self, keychain, connected_app=None, is_sandbox=False):
auth_url=auth_url,
is_sandbox=is_sandbox,
)
if info != self.config:
self.config.update(info)
else:
info = self._refresh_token(keychain, connected_app)
if info != self.config:
self.config.update(info)
# With refresh token rotation, each refresh invalidates the refresh token
# it used and the access token issued before it, and reusing an old refresh
# token revokes the whole token family. So under a lock, start from the
# latest stored tokens, refresh only if the stored access token no longer
# works (which would end other cci processes' sessions), and save the new
# tokens at once.
with self._refresh_lock():
self._load_latest_tokens()
if not (self.refresh_token_rotation and self._access_token_works()):
info = self._refresh_token(keychain, connected_app)
new_refresh_token = info.get("refresh_token")
rotated = (
new_refresh_token
and new_refresh_token != self.refresh_token
)
self.config.update(info)
if rotated:
self.config["refresh_token_rotation"] = True
if self.keychain:
# save() would take the lock again, which is already held
self.keychain.set_org(self, self.global_org)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Should fix] Taking the lock twice in one process blocks for 60s

The comment above explains that set_org is used because save() would take the lock again. Each org_lock() call creates a new FileLock, and on Unix flock locks belong to the open file descriptor. So if one process takes the lock twice, the second attempt blocks for ORG_LOCK_TIMEOUT and then raises Timeout. Any later change that calls save() (or something that calls it) inside this block will hit that.

Suggestions:

  • Use FileLock(..., is_singleton=True) (or cache one lock per path) so taking it twice in the same process is safe
  • filelock is added to pyproject.toml with no version floor. Please add a minimum (e.g. the version where is_singleton was added) so older installs don't behave differently

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed. FileLock(..., is_singleton=True), so the refresh path now calls save() directly. The pin is filelock>=3.15.2: is_singleton came in 3.13.0, but singleton fixes kept landing until 3.15.2.

self._load_userinfo()
self._load_orginfo()

def _refresh_lock(self):
if self.keychain and self.name:
return self.keychain.org_lock(self.name, self.global_org)
return nullcontext()

def _load_latest_tokens(self):
"""Use the tokens as currently stored in the keychain, in case
another process rotated them after this org config was loaded."""
if not self.keychain or not self.name:
return
try:
stored_config = self.keychain.reload_org(self.name).config
except OrgNotFound:
return
stored_token = stored_config.get("refresh_token")
if stored_token and stored_token != self.refresh_token:
for key in ("refresh_token", "access_token", "refresh_token_rotation"):
if key in stored_config:
self.config[key] = stored_config[key]

def _access_token_works(self) -> bool:
if not self.access_token:
return False
response = requests.get(

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Fix before merge] Network calls run while the lock is held, with no timeout

This requests.get (and the token POST in _refresh_token) runs while the per-org file lock is held, and neither call has a timeout. If either one hangs (VPN drop, proxy, Salesforce maintenance), the lock stays held indefinitely. Every other cci process on that org then waits ORG_LOCK_TIMEOUT (60s) and fails with a raw filelock.Timeout.

filelock.Timeout isn't a CumulusCIException, so users see something like:

Error: The file lock '/Users/.../.cumulusci/<project>/dev.org.lock' could not be acquired.

Suggestions:

  • Pass an explicit timeout= to both HTTP calls (ideally well under ORG_LOCK_TIMEOUT)
  • Catch filelock.Timeout in _refresh_lock/org_lock and raise a CumulusCIException that says another cci process is refreshing org X and to retry

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed. The userinfo GET times out after 20s (USERINFO_TIMEOUT). The refresh POST only gets a 10s connect timeout (TOKEN_REFRESH_TIMEOUT = (10, None)), because it isn't safe to retry under rotation: if Salesforce rotated the token and the response timed out, the next run would send the old token and revoke the whole family. In that rare case, waiting processes get the lock timeout instead, which is safe. filelock.Timeout becomes a CumulusCIException: "Timed out after 60 seconds waiting for another cci process to finish updating org X. Try again."

self.instance_url + "/services/oauth2/userinfo",
headers={"Authorization": "Bearer " + self.access_token},
)
if response.status_code in (401, 403):
return False
# Other errors, like a 503 during maintenance, don't mean the token is dead,
# and refreshing anyway would end other cci processes' sessions.
response.raise_for_status()
return True

@contextmanager
def save_if_changed(self):
orig_config = self.config.copy()
Expand Down Expand Up @@ -150,7 +210,16 @@ def _refresh_token(self, keychain, connected_app):
scope="web full refresh_token",
)
sf_oauth = self.OAuth2Client(sf_oauth_config)
return sf_oauth.refresh_token(self.refresh_token)
try:
return sf_oauth.refresh_token(self.refresh_token)
except OAuth2Error as e:
if "invalid_grant" not in str(e):
raise
raise OAuth2Error(

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Should fix] The new message hides Salesforce's error_description

handle_exception in cli/cci.py prints only str(error); the chained from e goes only to the log file. invalid_grant isn't always an expired or revoked token. Salesforce also returns it for inactive user, ip restricted, user hasn't approved this consumer, authentication failure, and a sandbox/prod login URL mix-up. In those cases, telling the user to run cci org connect sends them the wrong way.

Suggestion: parse the response and include error_description, e.g.

The refresh token for org dev is no longer valid (Salesforce said: "expired access/refresh token"). ...

Small nit: matching on "invalid_grant" in str(e) is fragile. Exposing the status/JSON on OAuth2Error would make this sturdier.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed. OAuth2Error now carries response. The message is "Salesforce rejected the refresh token for org X: <error_description>. If the token expired from inactivity or was revoked, run cci org connect X...". It matches on the JSON error field, not on a substring.

f"The refresh token for org {self.name} is no longer valid. "
"It may have expired from inactivity or been revoked. "
f"Run `cci org connect {self.name}` to connect the org again."
) from e

@property
def lightning_base_url(self):
Expand Down Expand Up @@ -370,7 +439,14 @@ def reset_installed_packages(self):

def save(self):
assert self.keychain, "Keychain was not set on OrgConfig"
self.keychain.set_org(self, self.global_org)
if self.refresh_token_rotation:

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[Fix before merge] Only processes that already have the rotation flag are protected here

The lock and merge in save() depend on the in-memory refresh_token_rotation. If a process loaded the org before rotation was ever detected, it has no flag and writes its out-of-date tokens with a plain set_org, without the lock.

Reproduced:

  1. Process A loads the org (TOKEN_1, no flag)
  2. Process B refreshes, rotates, and saves TOKEN_2 + refresh_token_rotation: True
  3. A changes something and calls save() without refreshing first
STORED AFTER A.save(): TOKEN_1 None

The dead token is back in the file and the flag is gone, so the next command reuses TOKEN_1 and the family gets revoked.

Suggestion: also look at the flag in the stored file. Or always take the lock and merge tokens for orgs that use refresh tokens (it's cheap). Be careful not to break cci org connect re-connects, which should replace the stored tokens.

Related, but code can't fix it: an older cci version sharing ~/.cumulusci (e.g. a pipx install alongside a project venv) will always write back out-of-date tokens. That's worth a release note.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed. save() now locks and merges for any org with a refresh token, using the same "changed since loaded" check. Org configs that didn't come from the keychain (cci org connect) still replace the stored tokens. Tests: test_save__keeps_first_rotation_by_another_process, test_save__connected_org_replaces_stored_tokens. The older-cci-sharing-~/.cumulusci case goes in the release notes.

# Another cci process may have rotated the tokens since this org was
# loaded. Saving the old ones would bring back a dead refresh token.
with self._refresh_lock():
self._load_latest_tokens()
self.keychain.set_org(self, self.global_org)
else:
self.keychain.set_org(self, self.global_org)

def get_domain(self):
instance_url = self.config.get("instance_url", "")
Expand Down
225 changes: 225 additions & 0 deletions cumulusci/core/config/tests/test_config.py
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
from unittest import mock

import pytest
import requests
import responses
import yaml
from github3.exceptions import NotFoundError
Expand Down Expand Up @@ -41,6 +42,7 @@
BaseProjectKeychain,
)
from cumulusci.core.source import LocalFolderSource
from cumulusci.oauth.exceptions import OAuth2Error
from cumulusci.tests.util import CURRENT_SF_API_VERSION, DummyKeychain
from cumulusci.utils import temporary_dir, touch
from cumulusci.utils.version_strings import StrictVersion
Expand Down Expand Up @@ -914,6 +916,229 @@ def test_refresh_oauth_token__other_connected_app(self, OAuth2Client):
assert client_config.client_id == "OTHER_ID"
refresh_token.assert_called_once_with(mock.sentinel.refresh_token)

def _org_config_in_keychain(self, refresh_token="OLD_TOKEN"):
project_config = BaseProjectConfig(UniversalConfig())
keychain = BaseProjectKeychain(project_config, None)
config = OrgConfig(
{
"refresh_token": refresh_token,
"instance_url": "http://instance_url_111.com",
},
"test",
keychain=keychain,
)
keychain.set_org(config)
config._load_userinfo = mock.Mock()
config._load_orginfo = mock.Mock()
return config, keychain

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotated_token_is_saved(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
OAuth2Client.return_value.refresh_token.return_value = {
"access_token": "asdf",
"refresh_token": "NEW_TOKEN",
}

with mock.patch.object(keychain, "set_org") as save:
config.refresh_oauth_token(keychain)

assert config.refresh_token == "NEW_TOKEN"
assert config.refresh_token_rotation
save.assert_called_once()

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotated_token_without_keychain(self, OAuth2Client):
config = OrgConfig(
{
"refresh_token": "OLD_TOKEN",
"instance_url": "http://instance_url_111.com",
},
"test",
)
config._load_userinfo = mock.Mock()
config._load_orginfo = mock.Mock()
keychain = BaseProjectKeychain(BaseProjectConfig(UniversalConfig()), None)
OAuth2Client.return_value.refresh_token.return_value = {
"access_token": "asdf",
"refresh_token": "NEW_TOKEN",
}

with mock.patch.object(keychain, "set_org") as save:
config.refresh_oauth_token(keychain)

assert config.refresh_token == "NEW_TOKEN"
assert config.refresh_token_rotation
save.assert_not_called()

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__unrotated_token_is_not_saved(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
OAuth2Client.return_value.refresh_token.return_value = {
"access_token": "asdf",
}

with mock.patch.object(keychain, "set_org") as save:
config.refresh_oauth_token(keychain)

assert config.refresh_token == "OLD_TOKEN"
save.assert_not_called()

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__uses_latest_stored_tokens(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
stored_org = OrgConfig(
{"refresh_token": "STORED_TOKEN", "access_token": "STORED_ACCESS"}, "test"
)
refresh_token = OAuth2Client.return_value.refresh_token
refresh_token.return_value = {"access_token": "asdf"}

with mock.patch.object(keychain, "reload_org", return_value=stored_org):
with mock.patch.object(config, "_access_token_works") as works:
config.refresh_oauth_token(keychain)

refresh_token.assert_called_once_with("STORED_TOKEN")
works.assert_not_called()

@responses.activate
@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotation_reuses_working_access_token(
self, OAuth2Client
):
config, keychain = self._org_config_in_keychain()
config.config.update(
{"access_token": "WORKING", "refresh_token_rotation": True}
)
responses.add(
responses.GET, "http://instance_url_111.com/services/oauth2/userinfo"
)

with mock.patch.object(keychain, "set_org") as save:
config.refresh_oauth_token(keychain)

OAuth2Client.return_value.refresh_token.assert_not_called()
save.assert_not_called()
assert config.access_token == "WORKING"
assert config.refresh_token == "OLD_TOKEN"
assert responses.calls[0].request.headers["Authorization"] == "Bearer WORKING"

@pytest.mark.parametrize("userinfo_status", [401, 403])
@responses.activate
@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotation_refreshes_expired_access_token(
self, OAuth2Client, userinfo_status
):
config, keychain = self._org_config_in_keychain()
config.config.update(
{"access_token": "EXPIRED", "refresh_token_rotation": True}
)
responses.add(
responses.GET,
"http://instance_url_111.com/services/oauth2/userinfo",
status=userinfo_status,
)
refresh_token = OAuth2Client.return_value.refresh_token
refresh_token.return_value = {
"access_token": "NEW_ACCESS",
"refresh_token": "NEW_TOKEN",
}

with mock.patch.object(keychain, "set_org") as save:
config.refresh_oauth_token(keychain)

refresh_token.assert_called_once_with("OLD_TOKEN")
save.assert_called_once()
assert config.access_token == "NEW_ACCESS"
assert config.refresh_token == "NEW_TOKEN"

@responses.activate
@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotation_userinfo_error(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
config.config.update(
{"access_token": "WORKING", "refresh_token_rotation": True}
)
responses.add(
responses.GET,
"http://instance_url_111.com/services/oauth2/userinfo",
status=503,
)

with pytest.raises(requests.exceptions.HTTPError):
config.refresh_oauth_token(keychain)

OAuth2Client.return_value.refresh_token.assert_not_called()

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__rotation_without_access_token(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
config.config["refresh_token_rotation"] = True
refresh_token = OAuth2Client.return_value.refresh_token
refresh_token.return_value = {"access_token": "asdf"}

config.refresh_oauth_token(keychain)

refresh_token.assert_called_once_with("OLD_TOKEN")

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__org_not_in_keychain(self, OAuth2Client):
project_config = BaseProjectConfig(UniversalConfig())
keychain = BaseProjectKeychain(project_config, None)
config = OrgConfig(
{
"refresh_token": "OLD_TOKEN",
"instance_url": "http://instance_url_111.com",
},
"test",
keychain=keychain,
)
config._load_userinfo = mock.Mock()
config._load_orginfo = mock.Mock()
refresh_token = OAuth2Client.return_value.refresh_token
refresh_token.return_value = {"access_token": "asdf"}

config.refresh_oauth_token(keychain)

refresh_token.assert_called_once_with("OLD_TOKEN")

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__holds_org_lock(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
lock = mock.MagicMock()

def refresh_token(token):
lock.__enter__.assert_called_once()
lock.__exit__.assert_not_called()
return {"access_token": "asdf"}

OAuth2Client.return_value.refresh_token.side_effect = refresh_token

with mock.patch.object(keychain, "org_lock", return_value=lock) as org_lock:
config.refresh_oauth_token(keychain)

org_lock.assert_called_once_with("test", False)
lock.__exit__.assert_called_once()

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__invalid_grant(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
OAuth2Client.return_value.refresh_token.side_effect = OAuth2Error(
'OAuth failed\nstatus_code: 400\ncontent: b\'{"error":"invalid_grant"}\''
)

with pytest.raises(OAuth2Error, match="Run `cci org connect test`"):
config.refresh_oauth_token(keychain)

@mock.patch("cumulusci.core.config.org_config.OrgConfig.OAuth2Client")
def test_refresh_oauth_token__other_oauth_error(self, OAuth2Client):
config, keychain = self._org_config_in_keychain()
OAuth2Client.return_value.refresh_token.side_effect = OAuth2Error(
"OAuth failed\nstatus_code: 500"
)

with pytest.raises(OAuth2Error, match="status_code: 500"):
config.refresh_oauth_token(keychain)

@responses.activate
def test_load_user_info__bad_json(self):
config = OrgConfig(
Expand Down
Loading
Loading