diff --git a/src/optimizer/app.py b/src/optimizer/app.py index a355b2d1c..922fa03ad 100644 --- a/src/optimizer/app.py +++ b/src/optimizer/app.py @@ -74,16 +74,29 @@ 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') + + 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), + } + # 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 # Namespace for the API @@ -218,23 +231,21 @@ 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 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..e9efd8b55 --- /dev/null +++ b/tests/test_bad_request.py @@ -0,0 +1,132 @@ +import json +from unittest.mock import ANY + +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', + 'client': ANY, + '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', + 'client': ANY, + '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', + 'client': ANY, + 'reason': 'Input payload validation failed', + 'fields': [field], + 'validator': validator, + } + + +@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 + 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', + 'client': ANY, + 'reason': 'All time series must have the same length', + 'fields': [], + 'validator': None, + 'lengths': lengths, + } + + +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') + + 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