Skip to content

Commit b5e1f64

Browse files
authored
Merge pull request #881 from OpenKnowledgeMaps/dev
Improve content provider caching behavior
2 parents 9e1df53 + b4a313f commit b5e1f64

12 files changed

Lines changed: 388 additions & 41 deletions

File tree

docker-compose.yml

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,11 +53,14 @@ services:
5353
BEHIND_PROXY: "${BEHIND_PROXY}"
5454
DEFAULT_DATABASE: "${DEFAULT_DATABASE}"
5555
FLASK_ENV: "${FLASK_ENV}"
56+
LOGLEVEL: "${LOGLEVEL}"
57+
LOGFILE: "/var/log/api/api.log"
5658
command: ["python", "app.py"]
5759
volumes:
5860
- ./api_cache:/var/api_cache
5961
- ./server/workers/api/src:/api
6062
- ./server/workers/common:/api/common
63+
- /var/log/api:/var/log/api
6164
depends_on:
6265
- redis
6366
- base

server/workers/api/src/apis/base.py

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -9,11 +9,11 @@
99
from .request_validators import SearchParamSchema
1010
from common.utils import get_key, redis_store, get_or_create_contentprovider_lookup
1111

12-
contentprovider_lookup = get_or_create_contentprovider_lookup()
13-
1412
base_ns = Namespace("base", description="BASE API operations")
1513
search_param_schema = SearchParamSchema()
1614

15+
contentprovider_lookup = get_or_create_contentprovider_lookup(logger=base_ns.logger)
16+
1717

1818
base_querymodel = base_ns.model("SearchQuery",
1919
{"q": fields.String(example='feminicide',
@@ -84,7 +84,7 @@ def post(self):
8484
base_ns.logger.debug(d)
8585
redis_store.rpush("base", json.dumps(d))
8686
q_len = redis_store.llen("base")
87-
base_ns.logger.debug("Queue length: %s %d %s" %("base", q_len, request_id))
87+
base_ns.logger.info("Queue length: %s %d %s" %("base", q_len, request_id))
8888
result = get_key(redis_store, request_id, 300)
8989
try:
9090
result, headers = set_response_headers(request.headers["Accept"], params.get("raw"), result, request_id)

server/workers/api/src/apis/create_vis.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ def post(self):
6060
"input_data": input_data}
6161
redis_store.rpush("input_data", json.dumps(d).encode('utf8'))
6262
q_len = redis_store.llen("input_data")
63-
vis_ns.logger.debug("Queue length: %s %d %s" %("input_data", q_len, request_id))
63+
vis_ns.logger.info("Queue length: %s %d %s" %("input_data", q_len, request_id))
6464
result = get_key(redis_store, request_id)
6565
try:
6666
result, headers = set_response_headers(request.headers["Accept"], params.get("raw"), result, request_id)

server/workers/api/src/apis/openaire.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ def post(self):
7070
openaire_ns.logger.debug(d)
7171
redis_store.rpush("openaire", json.dumps(d))
7272
q_len = redis_store.llen("openaire")
73-
openaire_ns.logger.debug("Queue length: %s %d %s" % ("openaire", q_len, k))
73+
openaire_ns.logger.info("Queue length: %s %d %s" % ("openaire", q_len, k))
7474
result = get_key(redis_store, k, 300)
7575
try:
7676
# Call the utility function once.

server/workers/api/src/apis/orcid.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ def post(self):
6060
redis_store.rpush("orcid", json.dumps(task_data))
6161

6262
queue_length = redis_store.llen("orcid")
63-
orcid_ns.logger.debug(f"Queue length: orcid {queue_length} {request_id}")
63+
orcid_ns.logger.info(f"Queue length: orcid {queue_length} {request_id}")
6464

6565
result = get_key(redis_store, request_id, REDIS_TIMEOUT)
6666
headers = self.get_response_headers()

server/workers/api/src/apis/pubmed.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -79,7 +79,7 @@ def post(self):
7979
pubmed_ns.logger.debug(request_data)
8080
redis_store.rpush("pubmed", json.dumps(request_data))
8181
queue_length = redis_store.llen("pubmed")
82-
pubmed_ns.logger.debug("Queue length: %s %d %s" % ("pubmed", queue_length, request_id))
82+
pubmed_ns.logger.info("Queue length: %s %d %s" % ("pubmed", queue_length, request_id))
8383

8484
# Get the result
8585
result = get_key(redis_store, request_id)

server/workers/api/src/app.py

Lines changed: 17 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -33,10 +33,20 @@ def api_patches(app):
3333
app = Flask('v1', instance_relative_config=True)
3434
# Configure logging
3535
app.logger.setLevel(os.getenv("LOGLEVEL") or logging.DEBUG)
36+
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
3637
handler = logging.StreamHandler(sys.stdout)
37-
handler.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
38+
handler.setFormatter(formatter)
3839
app.logger.addHandler(handler)
3940

41+
# Optionally also write to a logfile so mtail can turn log lines (e.g.
42+
# "Queue length: ...") into Prometheus metrics. flask-restx copies these
43+
# handlers onto each namespace logger at add_namespace() time below.
44+
logfile = os.getenv("LOGFILE")
45+
if logfile:
46+
file_handler = logging.FileHandler(logfile)
47+
file_handler.setFormatter(formatter)
48+
app.logger.addHandler(file_handler)
49+
4050
app.wsgi_app = ProxyFix(app.wsgi_app, x_proto=1, x_port=1, x_for=1, x_host=1, x_prefix=1)
4151
app.wsgi_app = ReverseProxied(app.wsgi_app)
4252
CORS(app, expose_headers=["Content-Disposition", "Access-Control-Allow-Origin"])
@@ -50,6 +60,12 @@ def api_patches(app):
5060
api.add_namespace(orcid_ns, path='/orcid')
5161
api.add_namespace(aquanavi_ns, path='/aquanavi')
5262

63+
# Namespace loggers inherit app.logger's handlers (copied by add_namespace).
64+
# Disable propagation to the root logger to avoid every line being emitted
65+
# twice (once via these handlers, once via the Flask default root handler).
66+
for ns in (base_ns, pubmed_ns, openaire_ns, vis_ns, export_ns, orcid_ns, aquanavi_ns):
67+
ns.logger.propagate = False
68+
5369
app.logger.debug(app.config)
5470
app.logger.debug(app.url_map)
5571

Lines changed: 187 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,187 @@
1+
import json
2+
import time
3+
import threading
4+
from contextlib import contextmanager
5+
6+
import pytest
7+
from redis.exceptions import LockError
8+
9+
import common.utils as cu
10+
from common.utils import (
11+
get_contentprovider_records,
12+
get_or_create_contentprovider_lookup,
13+
CONTENTPROVIDER_RECORDS_KEY,
14+
)
15+
16+
RECORDS = [
17+
{"name": "Université de Lausanne", "internal_name": "ftunivlausanne"},
18+
{"name": "Some Repo", "internal_name": "ftsomerepo"},
19+
]
20+
21+
22+
# --- Minimal in-memory Redis double supporting get / set(ex) / lock -----------
23+
24+
class FakeRedis:
25+
def __init__(self, fail_lock=False):
26+
self.store = {}
27+
self.last_ex = None
28+
self._fail_lock = fail_lock
29+
self._lock = threading.Lock()
30+
31+
def get(self, key):
32+
return self.store.get(key)
33+
34+
def set(self, key, value, ex=None):
35+
self.store[key] = value
36+
self.last_ex = ex
37+
38+
@contextmanager
39+
def lock(self, name, timeout=None, blocking_timeout=None):
40+
if self._fail_lock:
41+
raise LockError("could not acquire lock")
42+
acquired = self._lock.acquire(
43+
timeout=blocking_timeout if blocking_timeout is not None else -1
44+
)
45+
if not acquired:
46+
raise LockError("lock acquisition timed out")
47+
try:
48+
yield
49+
finally:
50+
self._lock.release()
51+
52+
53+
# --- get_contentprovider_records ---------------------------------------------
54+
55+
def test_cache_hit_skips_producer():
56+
r = FakeRedis()
57+
r.set(CONTENTPROVIDER_RECORDS_KEY, json.dumps(RECORDS))
58+
calls = []
59+
60+
out = get_contentprovider_records(r, lambda: calls.append(1) or [])
61+
62+
assert out == RECORDS
63+
assert calls == [] # producer never called on a warm cache
64+
65+
66+
def test_cache_miss_produces_and_caches_with_ttl():
67+
r = FakeRedis()
68+
calls = []
69+
70+
def produce():
71+
calls.append(1)
72+
return RECORDS
73+
74+
out = get_contentprovider_records(r, produce, ttl=1234)
75+
76+
assert out == RECORDS
77+
assert calls == [1]
78+
assert json.loads(r.store[CONTENTPROVIDER_RECORDS_KEY]) == RECORDS
79+
assert r.last_ex == 1234
80+
81+
82+
def test_single_producer_under_contention():
83+
r = FakeRedis()
84+
counter = {"n": 0}
85+
counter_lock = threading.Lock()
86+
87+
def produce():
88+
with counter_lock:
89+
counter["n"] += 1
90+
time.sleep(0.2) # hold the lock long enough for others to contend
91+
return RECORDS
92+
93+
results = []
94+
95+
def worker():
96+
results.append(get_contentprovider_records(r, produce))
97+
98+
threads = [threading.Thread(target=worker) for _ in range(5)]
99+
for t in threads:
100+
t.start()
101+
for t in threads:
102+
t.join()
103+
104+
assert counter["n"] == 1 # exactly one fetch despite 5 concurrent callers
105+
assert all(res == RECORDS for res in results)
106+
107+
108+
def test_lock_contention_waits_for_published_cache():
109+
r = FakeRedis(fail_lock=True) # this caller can never acquire the lock
110+
111+
def publish_later():
112+
time.sleep(0.1)
113+
r.set(CONTENTPROVIDER_RECORDS_KEY, json.dumps(RECORDS))
114+
115+
t = threading.Thread(target=publish_later)
116+
t.start()
117+
118+
def produce_should_not_run():
119+
raise AssertionError("producer must not run when the lock is held elsewhere")
120+
121+
out = get_contentprovider_records(r, produce_should_not_run, poll_timeout=5)
122+
t.join()
123+
124+
assert out == RECORDS
125+
126+
127+
def test_producer_error_falls_back_to_bundled():
128+
r = FakeRedis()
129+
130+
def produce():
131+
raise RuntimeError("boom")
132+
133+
out = get_contentprovider_records(r, produce)
134+
135+
assert isinstance(out, list) and len(out) > 0
136+
assert {"name", "internal_name"} <= set(out[0].keys())
137+
138+
139+
def test_corrupt_cache_value_is_reproduced():
140+
r = FakeRedis()
141+
r.set(CONTENTPROVIDER_RECORDS_KEY, "not-json{")
142+
143+
out = get_contentprovider_records(r, lambda: RECORDS)
144+
145+
assert out == RECORDS
146+
147+
148+
def test_cache_hit_logs_debug_trace(caplog):
149+
r = FakeRedis()
150+
r.set(CONTENTPROVIDER_RECORDS_KEY, json.dumps(RECORDS))
151+
152+
with caplog.at_level("DEBUG"):
153+
get_contentprovider_records(r, lambda: [])
154+
155+
assert any(
156+
"contentprovider-cache: served" in rec.message for rec in caplog.records
157+
)
158+
159+
160+
def test_fallback_logs_warning(caplog):
161+
r = FakeRedis()
162+
163+
def produce():
164+
raise RuntimeError("boom")
165+
166+
with caplog.at_level("WARNING"):
167+
get_contentprovider_records(r, produce)
168+
169+
assert any(
170+
rec.levelname == "WARNING" and "bundled fallback" in rec.message
171+
for rec in caplog.records
172+
)
173+
174+
175+
# --- get_or_create_contentprovider_lookup (API forward map) ------------------
176+
177+
def test_get_or_create_builds_forward_lookup(monkeypatch):
178+
monkeypatch.setattr(
179+
cu, "get_contentprovider_records", lambda store, fn, **kw: RECORDS
180+
)
181+
182+
lookup = get_or_create_contentprovider_lookup()
183+
184+
assert lookup == {
185+
"ftunivlausanne": "Université de Lausanne",
186+
"ftsomerepo": "Some Repo",
187+
}

server/workers/base/src/base.py

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@
2727
import dateparser
2828
import sys
2929
from common.rate_limiter import RateLimiter
30+
from common.utils import get_contentprovider_records
3031

3132

3233
class BaseClient(RWrapper):
@@ -35,8 +36,11 @@ def __init__(self, *args):
3536
self.rate_limiter = RateLimiter(self.redis_store, "base-ratelimit", 1.5)
3637

3738
try:
38-
result = self.get_contentproviders()
39-
df = pd.DataFrame(json.loads(result["contentproviders"]))
39+
records = get_contentprovider_records(
40+
self.redis_store, self._fetch_contentprovider_records,
41+
logger=self.logger
42+
)
43+
df = pd.DataFrame(records)
4044
df.set_index("name", inplace=True)
4145
cp_dict = df.internal_name.to_dict()
4246
self.content_providers = cp_dict
@@ -156,6 +160,13 @@ def enrich_metadata(self, metadata):
156160
metadata = pd.concat([metadata, enrichment], axis=1)
157161
return metadata
158162

163+
def _fetch_contentprovider_records(self):
164+
"""Run the R fetch and return the parsed list of content provider records."""
165+
result = self.get_contentproviders()
166+
if result.get("status") == "error":
167+
raise RuntimeError("contentproviders fetch returned an error")
168+
return json.loads(result["contentproviders"])
169+
159170
def get_contentproviders(self):
160171
runner = os.path.abspath(os.path.join(self.wd, "run_base_contentproviders.R"))
161172
cmd = [self.command, runner, self.wd]
@@ -209,7 +220,7 @@ def handle_search(self, request_id, params):
209220
"input_data", json.dumps(res).encode("utf8")
210221
)
211222
q_len = self.redis_store.llen("input_data")
212-
self.logger.debug(
223+
self.logger.info(
213224
"Queue length: %s %d %s" % ("input_data", q_len, request_id)
214225
)
215226
except Exception as e:

server/workers/base/tests/unit/test_base.py

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -178,6 +178,18 @@ def dummy_popen_cp(cmd, stdin, stdout, stderr, encoding):
178178
assert cp_list[0]["name"] == "cp1"
179179
assert cp_list[0]["internal_name"] == "Provider1"
180180

181+
def test_fetch_contentprovider_records_parses(client_base):
182+
# get_contentproviders is stubbed by the fixture to a fixed payload.
183+
records = client_base._fetch_contentprovider_records()
184+
assert records == [{"name": "cp1", "internal_name": "Provider1"}]
185+
186+
187+
def test_fetch_contentprovider_records_raises_on_error(client_base):
188+
client_base.get_contentproviders = lambda: {"status": "error"}
189+
with pytest.raises(RuntimeError):
190+
client_base._fetch_contentprovider_records()
191+
192+
181193
# --- Tests for parser functions ---
182194

183195
def test_filter_duplicates():

0 commit comments

Comments
 (0)