feat(obs): nommer chaque requete, et rendre les pages d erreur audibles
OBS-005. Un 500 dans errors.log et les six lignes de app.log qui y menent n etaient relies que par leur horodatage — ce qui n est pas une relation des que le serveur traite plus d une requete a la fois. Et un utilisateur qui dit « ca a plante quand j ai clique sur enregistrer » ne donnait a personne de quoi chercher. Chaque requete recoit un identifiant, porte par toutes les lignes de journal qu elle produit, renvoye en X-Request-Id, et affiche sur la page 500 comme reference a citer. Il est **genere**, jamais lu depuis un en-tete entrant. Accepter celui du client serait pratique pour tracer a travers nginx, et permettrait aussi a n importe qui d ecrire du texte arbitraire — retours a la ligne compris — dans le fichier de journal. C est ainsi qu un journal cesse d etre une preuve. Il n y a de toute facon aucun proxy de confiance tant qu OPS-002 est ouvert. Le test correspondant assure sur l alphabet plutot qu en envoyant un retour a la ligne : le client de test de Werkzeug refuse d emettre un tel en-tete, donc l attaque ne peut meme pas etre construite par la, ce qui ne prouverait rien sur l application. **Defaut trouve en chemin, et repare.** Les cinq gabarits d erreur remplissent le bloc `content`, qui n existait que dans la branche authentifiee de la mise en page. Un visiteur deconnecte tombant sur une erreur — donc typiquement sur la page de connexion — recevait le logo, le selecteur de langue, et **aucun message**. Le code de statut etait bon, les journaux etaient bons, la page etait vide. Le <title> disait quand meme « 404 », ce qui explique en grande partie que personne ne l ait vu. Le bloc est desormais rendu dans les deux branches via self.content(), Jinja refusant deux blocs de meme nom. Un seul cote du if s execute, donc jamais de double rendu — et c est assure, pas suppose. 550 tests.
This commit is contained in:
GGThed
@@ -0,0 +1,214 @@
|
||||
"""Every request has a name, and its log lines carry it (OBS-005).
|
||||
|
||||
Before this, a 500 in errors.log and the lines in app.log that led to it were
|
||||
related only by their timestamps — which is not a relation once the server is
|
||||
handling more than one request at a time. And a user saying "it broke when I
|
||||
clicked save" gave nobody anything to grep for.
|
||||
|
||||
The id is deliberately generated, never read from an inbound header. That is
|
||||
the test worth reading in this file: accepting one would be convenient for
|
||||
tracing through nginx, and would also let any caller write arbitrary text —
|
||||
newlines included — into the log, which is how a log stops being evidence.
|
||||
"""
|
||||
|
||||
import logging
|
||||
import re
|
||||
|
||||
import pytest
|
||||
|
||||
from app.logging_config import NO_REQUEST, RequestIdFilter
|
||||
|
||||
ID_PATTERN = re.compile(r'^[0-9a-f]{16}$')
|
||||
|
||||
|
||||
class TestTheHeader:
|
||||
def test_every_response_carries_one(self, client):
|
||||
response = client.get('/auth/login')
|
||||
|
||||
assert ID_PATTERN.match(response.headers['X-Request-Id'])
|
||||
|
||||
def test_two_requests_get_different_ids(self, client):
|
||||
first = client.get('/auth/login').headers['X-Request-Id']
|
||||
second = client.get('/auth/login').headers['X-Request-Id']
|
||||
|
||||
assert first != second
|
||||
|
||||
def test_an_error_response_carries_one_too(self, client):
|
||||
"""The case it exists for."""
|
||||
response = client.get('/no-such-page')
|
||||
|
||||
assert response.status_code == 404
|
||||
assert ID_PATTERN.match(response.headers['X-Request-Id'])
|
||||
|
||||
|
||||
class TestInboundHeadersAreIgnored:
|
||||
"""The security property, not a convenience.
|
||||
|
||||
Waitress currently runs with trusted_proxy='*' (OPS-002), so anything in
|
||||
an inbound header comes from whoever sent the request.
|
||||
"""
|
||||
|
||||
def test_a_supplied_id_is_not_adopted(self, client):
|
||||
response = client.get('/auth/login', headers={'X-Request-Id': 'chosen-by-the-caller'})
|
||||
|
||||
assert response.headers['X-Request-Id'] != 'chosen-by-the-caller'
|
||||
assert ID_PATTERN.match(response.headers['X-Request-Id'])
|
||||
|
||||
def test_the_id_is_always_hex_so_it_cannot_forge_a_log_line(self, client):
|
||||
"""The property that makes log injection impossible.
|
||||
|
||||
A value carrying a newline writes a second line that looks exactly
|
||||
like a real log entry — that is how a log stops being evidence.
|
||||
Since the id is generated from a fixed alphabet rather than taken
|
||||
from the request, no input reaches the log through this field at all.
|
||||
|
||||
Asserted on the alphabet rather than by sending a newline: Werkzeug's
|
||||
test client refuses to send such a header, so the attack cannot even
|
||||
be constructed through it — which proves nothing about the app.
|
||||
"""
|
||||
for supplied in ('../../etc/passwd', 'a b c', '<script>', 'x' * 500):
|
||||
value = client.get('/auth/login', headers={'X-Request-Id': supplied}).headers[
|
||||
'X-Request-Id'
|
||||
]
|
||||
assert ID_PATTERN.match(value), f'{supplied!r} influenced the id'
|
||||
|
||||
|
||||
class TestTheFilter:
|
||||
"""RequestIdFilter has to be safe on records emitted from anywhere.
|
||||
|
||||
The Discord bot logs from its own thread, the scheduler from another, and
|
||||
configure_logging runs before any request exists. A filter that raised
|
||||
there would take the log down with it.
|
||||
"""
|
||||
|
||||
@pytest.fixture
|
||||
def record(self):
|
||||
return logging.LogRecord('app.test', logging.INFO, __file__, 1, 'hello', None, None)
|
||||
|
||||
def test_outside_a_request_the_record_still_gets_a_value(self, record):
|
||||
assert RequestIdFilter().filter(record) is True
|
||||
assert record.request_id == NO_REQUEST
|
||||
|
||||
def test_inside_a_request_it_gets_that_request_id(self, app, record):
|
||||
with app.test_request_context('/'):
|
||||
from flask import g
|
||||
|
||||
g.request_id = 'abcdef0123456789'
|
||||
RequestIdFilter().filter(record)
|
||||
|
||||
assert record.request_id == 'abcdef0123456789'
|
||||
|
||||
def test_a_request_without_the_before_request_hook_does_not_crash(self, app, record):
|
||||
"""g exists but the key does not — the case during app teardown, and
|
||||
in any test that pushes a bare context."""
|
||||
with app.test_request_context('/'):
|
||||
RequestIdFilter().filter(record)
|
||||
|
||||
assert record.request_id == NO_REQUEST
|
||||
|
||||
def test_the_formatter_never_raises_for_want_of_the_field(self, app, record, caplog):
|
||||
"""The formatter references %(request_id)s. A handler carrying that
|
||||
format without this filter raises on its first record — which would
|
||||
turn a logged error into a crash inside the error handler."""
|
||||
formatter = logging.Formatter('[%(request_id)s] %(message)s')
|
||||
RequestIdFilter().filter(record)
|
||||
|
||||
assert formatter.format(record) == f'[{NO_REQUEST}] hello'
|
||||
|
||||
|
||||
class TestTheErrorPage:
|
||||
"""Driven through a real failing request rather than by rendering the
|
||||
template: the id has to survive the whole path — before_request, the
|
||||
handler, the template — and rendering the file directly would skip all
|
||||
three."""
|
||||
|
||||
@pytest.fixture
|
||||
def exploding_app(self, app):
|
||||
app.config['PROPAGATE_EXCEPTIONS'] = False
|
||||
|
||||
@app.route('/tests/boom')
|
||||
def boom():
|
||||
raise RuntimeError('deliberate')
|
||||
|
||||
return app
|
||||
|
||||
def test_the_five_hundred_page_quotes_the_reference(self, exploding_app):
|
||||
"""Without it on the page, a user report cannot be tied to a trace."""
|
||||
client = exploding_app.test_client()
|
||||
|
||||
response = client.get('/tests/boom')
|
||||
|
||||
assert response.status_code == 500
|
||||
page = response.get_data(as_text=True)
|
||||
assert response.headers['X-Request-Id'] in page
|
||||
|
||||
def test_a_signed_out_visitor_sees_the_page_at_all(self, exploding_app):
|
||||
"""The error templates fill `content`, which used to exist only in
|
||||
the signed-in branch of the layout: anonymous visitors got the logo
|
||||
and nothing else, while the <title> still said 500."""
|
||||
page = exploding_app.test_client().get('/tests/boom').get_data(as_text=True)
|
||||
|
||||
assert 'error-container' in page
|
||||
|
||||
def test_the_json_paths_carry_it_too(self, exploding_app):
|
||||
"""A fetch that 500s gets the same reference, or the JavaScript half
|
||||
of the application is untraceable."""
|
||||
|
||||
@exploding_app.route('/users/api/boom')
|
||||
def api_boom():
|
||||
raise RuntimeError('deliberate')
|
||||
|
||||
response = exploding_app.test_client().get('/users/api/boom')
|
||||
|
||||
assert response.status_code == 500
|
||||
assert response.get_json()['request_id'] == response.headers['X-Request-Id']
|
||||
|
||||
|
||||
class TestErrorPagesSpeakToEveryone:
|
||||
"""Every error page must say something, signed in or not (found while
|
||||
adding the reference above).
|
||||
|
||||
The failure mode is quiet by construction: the <title> comes from a block
|
||||
outside the branch, so the tab said "404 — Page Not Found" over a page
|
||||
that carried no message. The status code was right, the logs were right,
|
||||
and the page was blank.
|
||||
"""
|
||||
|
||||
ERRORS = {
|
||||
400: '/tests/error/400',
|
||||
403: '/tests/error/403',
|
||||
404: '/no-such-page-anywhere',
|
||||
500: '/tests/error/500',
|
||||
}
|
||||
|
||||
@pytest.fixture
|
||||
def erroring_app(self, app):
|
||||
from flask import abort
|
||||
|
||||
app.config['PROPAGATE_EXCEPTIONS'] = False
|
||||
|
||||
@app.route('/tests/error/<int:code>')
|
||||
def raise_error(code):
|
||||
if code == 500:
|
||||
raise RuntimeError('deliberate')
|
||||
abort(code)
|
||||
|
||||
return app
|
||||
|
||||
@pytest.mark.parametrize('code', sorted(ERRORS))
|
||||
def test_a_signed_out_visitor_gets_the_message(self, erroring_app, code):
|
||||
response = erroring_app.test_client().get(self.ERRORS[code])
|
||||
|
||||
assert response.status_code == code
|
||||
page = response.get_data(as_text=True)
|
||||
assert 'error-container' in page, f'{code} renders no body for a signed-out visitor'
|
||||
|
||||
@pytest.mark.parametrize('code', sorted(ERRORS))
|
||||
def test_a_signed_in_visitor_gets_it_once_and_not_twice(self, erroring_app, as_role, code):
|
||||
"""`self.content()` sits in the other branch of the same `if`, so it
|
||||
can never double-render — asserted rather than assumed."""
|
||||
as_role('player')
|
||||
|
||||
page = erroring_app.test_client().get(self.ERRORS[code]).get_data(as_text=True)
|
||||
|
||||
assert page.count('error-container') <= 1
|
||||
Reference in New Issue
Block a user