From 3b6d84ad57f52c2a814b16fdcf5b8ebb176671f1 Mon Sep 17 00:00:00 2001 From: andig Date: Sat, 5 Sep 2026 18:49:39 +0200 Subject: [PATCH 1/3] fix: report and log bad requests without crashing --- src/optimizer/app.py | 26 +++++---- tests/test_bad_request.py | 114 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 130 insertions(+), 10 deletions(-) create mode 100644 tests/test_bad_request.py diff --git a/src/optimizer/app.py b/src/optimizer/app.py index a355b2d1c..329f8a82c 100644 --- a/src/optimizer/app.py +++ b/src/optimizer/app.py @@ -74,16 +74,20 @@ def dump_slow_request(payload, elapsed): @api.errorhandler(BadRequest) def handle_validation_error(error): - """Rename 'errors' to 'details' in validation responses.""" - if error.data and 'errors' in error.data: - error.data['details'] = error.data['errors'] - del error.data['errors'] - return error.data, 400 - elif error.data: - # plain api.abort(400, message) calls carry only a message - return error.data, 400 - else: - raise error + """Return JSON and log the cause without logging rejected request values.""" + data = getattr(error, 'data', None) + reason = data.get('message', error.description).partition(':')[0] if data else 'Invalid request body' + error.data = data or {'message': error.description} + if 'errors' in error.data: + error.data['details'] = error.data.pop('errors') + + print(json.dumps({'bad_request': { + 'path': request.path, + 'reason': reason, + 'fields': sorted(error.data.get('details', {})), + 'validator': getattr(error.__context__, 'validator', None), + }}), flush=True) + return error.data, 400 # Namespace for the API @@ -235,6 +239,8 @@ def post(self): if len(set(lengths)) > 1: api.abort(400, "All time series must have the same length") + except BadRequest: + raise except Exception as e: api.abort(400, f"Invalid data format: {str(e)}") diff --git a/tests/test_bad_request.py b/tests/test_bad_request.py new file mode 100644 index 000000000..072953b57 --- /dev/null +++ b/tests/test_bad_request.py @@ -0,0 +1,114 @@ +import json + +import pytest + +from optimizer.app import app + + +@pytest.fixture +def payload(): + return { + 'batteries': [{ + 's_min': 0, 's_max': 10000, 's_initial': 5000, + 'c_min': 0, 'c_max': 5000, 'd_max': 0, 'p_a': 0.0001, + }], + 'time_series': { + 'dt': [3600, 3600], 'gt': [1000, 1000], 'ft': [0, 0], + 'p_N': [0.0003, 0.0003], 'p_E': [0.0001, 0.0001], + }, + } + + +@pytest.mark.parametrize('body', ['', '{', 'private-invalid-body']) +def test_malformed_json_returns_400(body, capsys): + response = app.test_client().post('/optimize/charge-schedule', data=body, content_type='application/json') + + assert response.status_code == 400 + assert response.json['message'] + logged = capsys.readouterr().out + assert json.loads(logged)['bad_request'] == { + 'path': '/optimize/charge-schedule', + 'reason': 'Invalid request body', + 'fields': [], + 'validator': None, + } + assert 'private-invalid-body' not in logged + + +def test_missing_fields_are_logged(capsys): + response = app.test_client().post('/optimize/charge-schedule', json={}) + + assert response.status_code == 400 + assert set(response.json['details']) == {'batteries', 'time_series'} + assert 'errors' not in response.json + assert json.loads(capsys.readouterr().out)['bad_request'] == { + 'path': '/optimize/charge-schedule', + 'reason': 'Input payload validation failed', + 'fields': ['batteries', 'time_series'], + 'validator': 'required', + } + + +@pytest.mark.parametrize('validator', ['enum', 'type']) +def test_validation_logs_omit_request_values(payload, validator, capsys): + secret = 'private-request-value' + if validator == 'enum': + payload['strategy'] = {'charging_strategy': secret} + field = 'strategy.charging_strategy' + else: + payload['batteries'][0]['c_min'] = secret + field = 'batteries.0.c_min' + + response = app.test_client().post('/optimize/charge-schedule?token=private-query', json=payload, + headers={'Authorization': 'Bearer private-token'}) + + assert response.status_code == 400 + assert secret in json.dumps(response.json['details']) + logged = capsys.readouterr().out + assert 'private-' not in logged + assert json.loads(logged)['bad_request'] == { + 'path': '/optimize/charge-schedule', + 'reason': 'Input payload validation failed', + 'fields': [field], + 'validator': validator, + } + + +def test_length_mismatch_preserves_cause(payload, capsys): + payload['time_series']['p_N'] = [0.0003] + + response = app.test_client().post('/optimize/charge-schedule', json=payload) + + assert response.status_code == 400 + assert response.json == {'message': 'All time series must have the same length'} + assert json.loads(capsys.readouterr().out)['bad_request'] == { + 'path': '/optimize/charge-schedule', + 'reason': 'All time series must have the same length', + 'fields': [], + 'validator': None, + } + + +def test_conversion_error_logs_omit_exception_values(payload, monkeypatch, capsys): + def invalid_battery(**kwargs): + raise ValueError('private-exception-value') + + monkeypatch.setattr('optimizer.app.BatteryConfig', invalid_battery) + + response = app.test_client().post('/optimize/charge-schedule', json=payload) + + assert response.status_code == 400 + logged = capsys.readouterr().out + assert 'private-exception-value' not in logged + assert json.loads(logged)['bad_request']['reason'] == 'Invalid data format' + + +def test_other_statuses_do_not_log_bad_requests(payload, monkeypatch, capsys): + response = app.test_client().post('/optimize/charge-schedule', json=payload) + assert response.status_code == 200 + assert 'bad_request' not in capsys.readouterr().out + + monkeypatch.setenv('JWT_TOKEN_SECRET', 'test-secret') + response = app.test_client().post('/optimize/charge-schedule', json={}) + assert response.status_code == 401 + assert 'bad_request' not in capsys.readouterr().out From b732ea18c6a5379d4b3c7500a1a18c7fe4aacfb5 Mon Sep 17 00:00:00 2001 From: andig Date: Thu, 10 Sep 2026 09:44:15 +0200 Subject: [PATCH 2/3] fix: name the series in a length mismatch, and count dt among them Production rejects a steady eight to twelve requests an hour with "All time series must have the same length" and the log could not say which series was short, so the client bug behind it cannot be traced. The response and the log now carry every series length. Values stay out of the log as before, a length is shape, not content. dt was not among the validated series. The model indexes every series by it, so a short dt was an IndexError and a 500 instead of a 400 naming the series. Co-Authored-By: Claude Fable 5.1 --- src/optimizer/app.py | 38 ++++++++++++++++++++------------------ tests/test_bad_request.py | 11 ++++++++--- 2 files changed, 28 insertions(+), 21 deletions(-) diff --git a/src/optimizer/app.py b/src/optimizer/app.py index 329f8a82c..1d6425b14 100644 --- a/src/optimizer/app.py +++ b/src/optimizer/app.py @@ -81,12 +81,18 @@ def handle_validation_error(error): if 'errors' in error.data: error.data['details'] = error.data.pop('errors') - print(json.dumps({'bad_request': { + logged = { 'path': request.path, 'reason': reason, 'fields': sorted(error.data.get('details', {})), 'validator': getattr(error.__context__, 'validator', None), - }}), flush=True) + } + # series lengths are shape, not content: they say which series the client cut short, which + # is what a length mismatch needs traced to. Production logs a steady eight to twelve of + # them an hour with no way to tell gt from p_N. + if 'lengths' in error.data: + logged['lengths'] = error.data['lengths'] + print(json.dumps({'bad_request': logged}), flush=True) return error.data, 400 @@ -222,22 +228,18 @@ def post(self): p_E=data['time_series']['p_E'], ) - # Validate time series lengths - lengths = [len(time_series.gt), len(time_series.ft), - len(time_series.p_N), len(time_series.p_E)] - - # Validate p_demand if provided - for bat in batteries: - if bat.p_demand is not None: - lengths.append(len(bat.p_demand)) - - # Validate s_goal if provided - for bat in batteries: - if bat.s_goal is not None: - lengths.append(len(bat.s_goal)) - - if len(set(lengths)) > 1: - api.abort(400, "All time series must have the same length") + # Validate time series lengths. dt included: the model indexes every series by it, + # so a short dt was an IndexError and a 500 rather than a 400 naming the series. + lengths = { + 'dt': len(time_series.dt), 'gt': len(time_series.gt), 'ft': len(time_series.ft), + 'p_N': len(time_series.p_N), 'p_E': len(time_series.p_E), + 'p_demand': [len(bat.p_demand) for bat in batteries if bat.p_demand is not None], + 's_goal': [len(bat.s_goal) for bat in batteries if bat.s_goal is not None], + } + + if len({*[v for k, v in lengths.items() if k not in ('p_demand', 's_goal')], + *lengths['p_demand'], *lengths['s_goal']}) > 1: + api.abort(400, "All time series must have the same length", lengths=lengths) except BadRequest: raise diff --git a/tests/test_bad_request.py b/tests/test_bad_request.py index 072953b57..0d20b75c9 100644 --- a/tests/test_bad_request.py +++ b/tests/test_bad_request.py @@ -74,18 +74,23 @@ def test_validation_logs_omit_request_values(payload, validator, capsys): } -def test_length_mismatch_preserves_cause(payload, capsys): - payload['time_series']['p_N'] = [0.0003] +@pytest.mark.parametrize('series', ['p_N', 'dt']) +def test_length_mismatch_names_the_series(payload, series, capsys): + payload['time_series'][series] = payload['time_series'][series][:1] + payload['batteries'][0]['s_goal'] = [0, 5000] response = app.test_client().post('/optimize/charge-schedule', json=payload) assert response.status_code == 400 - assert response.json == {'message': 'All time series must have the same length'} + lengths = {'dt': 2, 'gt': 2, 'ft': 2, 'p_N': 2, 'p_E': 2, 'p_demand': [], 's_goal': [2]} + lengths[series] = 1 + assert response.json == {'message': 'All time series must have the same length', 'lengths': lengths} assert json.loads(capsys.readouterr().out)['bad_request'] == { 'path': '/optimize/charge-schedule', 'reason': 'All time series must have the same length', 'fields': [], 'validator': None, + 'lengths': lengths, } From c990d5ffa86d6f2e97918a38dc77a1e882ace261 Mon Sep 17 00:00:00 2001 From: andig Date: Thu, 10 Sep 2026 12:03:59 +0200 Subject: [PATCH 3/3] feat: log the client version on a rejected request evcc sends User-Agent evcc/ on every request. A rejected request is usually a client bug, and the version names the release carrying it: the empty solar forecast behind the length mismatches was fixed in evcc 0.309.0, which the log could not tell. Co-Authored-By: Claude Fable 5.1 --- src/optimizer/app.py | 3 +++ tests/test_bad_request.py | 13 +++++++++++++ 2 files changed, 16 insertions(+) diff --git a/src/optimizer/app.py b/src/optimizer/app.py index 1d6425b14..922fa03ad 100644 --- a/src/optimizer/app.py +++ b/src/optimizer/app.py @@ -83,6 +83,9 @@ def handle_validation_error(error): logged = { 'path': request.path, + # evcc stamps its version on every request as evcc/. A rejected request is + # usually a client bug, and the version is what says which release carries it. + 'client': request.headers.get('User-Agent'), 'reason': reason, 'fields': sorted(error.data.get('details', {})), 'validator': getattr(error.__context__, 'validator', None), diff --git a/tests/test_bad_request.py b/tests/test_bad_request.py index 0d20b75c9..e9efd8b55 100644 --- a/tests/test_bad_request.py +++ b/tests/test_bad_request.py @@ -1,4 +1,5 @@ import json +from unittest.mock import ANY import pytest @@ -28,6 +29,7 @@ def test_malformed_json_returns_400(body, capsys): logged = capsys.readouterr().out assert json.loads(logged)['bad_request'] == { 'path': '/optimize/charge-schedule', + 'client': ANY, 'reason': 'Invalid request body', 'fields': [], 'validator': None, @@ -43,6 +45,7 @@ def test_missing_fields_are_logged(capsys): assert 'errors' not in response.json assert json.loads(capsys.readouterr().out)['bad_request'] == { 'path': '/optimize/charge-schedule', + 'client': ANY, 'reason': 'Input payload validation failed', 'fields': ['batteries', 'time_series'], 'validator': 'required', @@ -68,6 +71,7 @@ def test_validation_logs_omit_request_values(payload, validator, capsys): assert 'private-' not in logged assert json.loads(logged)['bad_request'] == { 'path': '/optimize/charge-schedule', + 'client': ANY, 'reason': 'Input payload validation failed', 'fields': [field], 'validator': validator, @@ -87,6 +91,7 @@ def test_length_mismatch_names_the_series(payload, series, capsys): assert response.json == {'message': 'All time series must have the same length', 'lengths': lengths} assert json.loads(capsys.readouterr().out)['bad_request'] == { 'path': '/optimize/charge-schedule', + 'client': ANY, 'reason': 'All time series must have the same length', 'fields': [], 'validator': None, @@ -94,6 +99,14 @@ def test_length_mismatch_names_the_series(payload, series, capsys): } +def test_client_version_is_logged(payload, capsys): + payload['time_series']['p_N'] = [0.0003] + + app.test_client().post('/optimize/charge-schedule', json=payload, headers={'User-Agent': 'evcc/0.308.1'}) + + assert json.loads(capsys.readouterr().out)['bad_request']['client'] == 'evcc/0.308.1' + + def test_conversion_error_logs_omit_exception_values(payload, monkeypatch, capsys): def invalid_battery(**kwargs): raise ValueError('private-exception-value')