fix: log HTTP 400 causes and handle malformed JSON

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/<version>. 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)}")
 

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