diff --git a/libstat/forms/survey.py b/libstat/forms/survey.py index 26aa687..00d5c05 100644 --- a/libstat/forms/survey.py +++ b/libstat/forms/survey.py @@ -187,10 +187,10 @@ def _cell_to_input_field(self, cell, observation, authenticated, variable_type): if isinstance(field.initial, str): field.initial = field.initial.strip() - if cell.variable_key == "Besok01": - logger.debug("attrs:") - for attr, value in list(attrs.items()): - logger.debug(attr) + #if cell.variable_key == "Besok01": + # logger.debug("attrs:") + # for attr, value in list(attrs.items()): + # logger.debug(attr) return field diff --git a/libstat/models.py b/libstat/models.py index 4dbec54..772f6a4 100644 --- a/libstat/models.py +++ b/libstat/models.py @@ -546,7 +546,17 @@ def is_published(self): @property def latest_version_published(self): - return self.published_at is not None and self.published_at >= self.date_modified + # It can happen that self.modified_at is a timezone-unaware datetime object + # causing an error when compared with self.published_at ("can't compare offset-naive + # and offset-aware datetimes"). datetime.utcnow() is used in various places and does + # *not* set tzinfo. We shouldn't have these kinds of problems, but I'd rather not + # start poking at date/time handling given the state of the code, so let's just work + # around it here. + modified_at_with_tz = self.date_modified + if self.published_at is not None and self.published_at.tzinfo: + if not self.date_modified.tzinfo: + modified_at_with_tz = modified_at_with_tz.replace(tzinfo=self.published_at.tzinfo) + return self.published_at is not None and self.published_at >= modified_at_with_tz def target_group__desc(self): return targetGroups[self.target_group] diff --git a/libstat/utils.py b/libstat/utils.py index 27c7d53..d8be74e 100644 --- a/libstat/utils.py +++ b/libstat/utils.py @@ -1,6 +1,7 @@ -# -*- coding: UTF-8 -*- import datetime +from ipware import IpWare + ALL_TARGET_GROUPS_label = "Samtliga bibliotek" SURVEY_TARGET_GROUPS = ( ("natbib", "Nationalbibliotek"), @@ -68,6 +69,8 @@ ISO8601_utc_format = "%Y-%m-%dT%H:%M:%S.%fZ" +ipw = IpWare() + def parse_datetime_from_isodate_str(date_str): # Note: Timezone designator not supported ("+01:00"). @@ -95,3 +98,23 @@ def parse_datetime(date_str, date_format): return datetime.datetime.strptime(date_str, date_format) except ValueError: return None + + +def get_ip_for_logging(request): + # We use ipware (ipw) tp easily get the "real" client IP. + # Might need some adjustments depending on the environment, e.g. specifying + # trusted proxies. + # This is *ONLY* for logging purposes. + ip, trusted_route = ipw.get_client_ip(request.META) + return ip + + +def get_log_prefix(request, survey_id=None, survey_title=None): + log_prefix = f"[IP: {get_ip_for_logging(request)}]" + if request.user.is_superuser: + log_prefix = f"{log_prefix} [ADMIN]" + if survey_id: + log_prefix = f"{log_prefix} [survey: {survey_id}]" + if survey_title: + log_prefix = f"{log_prefix} [{survey_title}]" + return log_prefix diff --git a/libstat/views/dispatches.py b/libstat/views/dispatches.py index 79c49fb..1b9fa7a 100644 --- a/libstat/views/dispatches.py +++ b/libstat/views/dispatches.py @@ -8,6 +8,7 @@ from bibstat import settings from libstat.models import Dispatch, Survey +from libstat.utils import get_log_prefix logger = logging.getLogger(__name__) @@ -35,6 +36,7 @@ def _rendered_template(template, survey): def dispatches(request): if request.method == "POST": survey_ids = request.POST.getlist("survey-response-ids", []) + logger.info(f"{get_log_prefix(request)} Creating dispatches for {survey_ids}") surveys = list(Survey.objects.filter(id__in=survey_ids).exclude("observations")) dispatches = [ @@ -67,6 +69,7 @@ def dispatches(request): def dispatches_delete(request): if request.method == "POST": dispatch_ids = request.POST.getlist("dispatch-ids", []) + logger.info(f"{get_log_prefix(request)} Deleting dispatches {dispatch_ids}") Dispatch.objects.filter(id__in=dispatch_ids).delete() message = "" @@ -83,6 +86,7 @@ def dispatches_delete(request): def dispatches_send(request): if request.method == "POST": dispatch_ids = request.POST.getlist("dispatch-ids", []) + logger.info(f"{get_log_prefix(request)} Sending dispatches {dispatch_ids}") dispatches = Dispatch.objects.filter(id__in=dispatch_ids) dispatches_with_email = [ dispatch for dispatch in dispatches if dispatch.library_email diff --git a/libstat/views/survey.py b/libstat/views/survey.py index 13e30cf..db2c90f 100644 --- a/libstat/views/survey.py +++ b/libstat/views/survey.py @@ -23,6 +23,7 @@ ) from libstat.forms.survey import SurveyForm from libstat.survey_templates import survey_template +from libstat.utils import get_log_prefix logger = logging.getLogger(__name__) @@ -68,7 +69,7 @@ def sigel_survey(request, sigel): return HttpResponseNotFound() -def _save_survey_response_from_form(survey, form): +def _save_survey_response_from_form(survey, form, log_prefix): # Note: all syntax/format validation is done on client side w Bootstrap validator. # All fields are handled as CharFields in the form and casted based on variable.type before saving. # More types can be added when needed. @@ -108,9 +109,13 @@ def _save_survey_response_from_form(survey, form): _f for _f in form.cleaned_data["selected_libraries"].split(" ") if _f ] + logger.info(f"{log_prefix} Saving form; submit_action={submit_action}, survey_status={survey.status}") if submit_action == "submit" and survey.status in ("not_viewed", "initiated"): if not survey.has_conflicts(): + logger.info(f"{log_prefix} submit_action was 'submit' and survey.status {survey.status}; changing status to submitted") survey.status = "submitted" + else: + logger.info(f"{log_prefix} submit_action was 'submit' and survey.status {survey.status}; however status NOT changed to submitted due to conflicts") survey.save(validate=False) @@ -147,8 +152,10 @@ def can_view_survey(survey): return HttpResponseNotFound() survey = survey[0] + log_prefix = get_log_prefix(request, survey_id, survey) if not survey.is_active and not request.user.is_authenticated: + logger.info(f"{log_prefix} tried to {request.method} but survey is not active and user is not authenticated") return HttpResponseForbidden() context = { @@ -164,6 +171,7 @@ def can_view_survey(survey): if can_view_survey(survey): if not request.user.is_authenticated and survey.status == "not_viewed": + logger.info(f"{log_prefix} User not authenticated and survey.status was not_viewed; setting survey.status to initiated and saving") survey.status = "initiated" survey.save(validate=False) @@ -174,7 +182,7 @@ def can_view_survey(survey): and not request.user.is_superuser ): logger.error( - f"Refusing to save because survey has status submitted (or higher), library {survey.library.sigel}" + f"{log_prefix} Refusing to save because survey has status submitted (or higher), library {survey.library.sigel}" ) return HttpResponse( json.dumps({"error": "Survey already submitted"}), @@ -182,12 +190,15 @@ def can_view_survey(survey): content_type="application/json", ) else: + logger.info(f"{log_prefix} POSTing survey") form = SurveyForm(request.POST, survey=survey) errors = _save_survey_response_from_form( - survey, form + survey, form, log_prefix ) # Errors returned as separate json - logger.debug("ERRORS: ") - logger.debug(json.dumps(errors)) + if errors: + logger.info(f"{log_prefix} Errors when saving survey: {json.dumps(errors)}") + else: + logger.info(f"{log_prefix} Survey saved") return HttpResponse(json.dumps(errors), content_type="application/json") else: @@ -232,6 +243,8 @@ def release_survey_lock(request, survey_id): def survey_status(request, survey_id): if request.method == "POST": survey = Survey.objects.get(pk=survey_id) + log_prefix = f"{get_log_prefix(request, survey_id, survey)}" + logger.info(f"{log_prefix} Changing selected_status from {survey.status} to {request.POST['selected_status']}") survey.status = request.POST["selected_status"] survey.save() @@ -242,6 +255,8 @@ def survey_status(request, survey_id): def survey_notes(request, survey_id): if request.method == "POST": survey = Survey.objects.get(pk=survey_id) + log_prefix = f"{get_log_prefix(request, survey_id, survey)}" + logger.info(f"{log_prefix} Adding notes to survey") survey.notes = request.POST["notes"] survey.save() diff --git a/libstat/views/surveys.py b/libstat/views/surveys.py index e59af88..f668ad3 100644 --- a/libstat/views/surveys.py +++ b/libstat/views/surveys.py @@ -33,6 +33,7 @@ ) from libstat.survey_templates import survey_template from data.municipalities import municipalities +from libstat.utils import get_log_prefix logger = logging.getLogger(__name__) @@ -147,6 +148,7 @@ def surveys(request, *args, **kwargs): def surveys_activate(request): if request.method == "POST": survey_ids = request.POST.getlist("survey-response-ids", []) + logger.info(f"{get_log_prefix(request)} Activating surveys {survey_ids}") Survey.objects.filter(pk__in=survey_ids).update(set__is_active=True) request.session["message"] = "Aktiverade {} stycken enkäter.".format( len(survey_ids) @@ -158,6 +160,7 @@ def surveys_activate(request): def surveys_inactivate(request): if request.method == "POST": survey_ids = request.POST.getlist("survey-response-ids", []) + logger.info(f"{get_log_prefix(request)} Inactivating surveys {survey_ids}") Survey.objects.filter(pk__in=survey_ids).update(set__is_active=False) request.session["message"] = "Inaktiverade {} stycken enkäter.".format( len(survey_ids) @@ -318,8 +321,10 @@ def surveys_overview(request, sample_year): @permission_required("is_superuser", login_url="index") def surveys_statuses(request): + log_prefix = f"{get_log_prefix(request)}" status = request.POST.get("new_status", "") survey_response_ids = request.POST.getlist("survey-response-ids", []) + logger.info(f"{log_prefix} Changing status for {survey_response_ids}") if status == "published": num_successful_published = 0 for survey in Survey.objects.filter(id__in=survey_response_ids): @@ -333,6 +338,9 @@ def surveys_statuses(request): "de svarar för några bibliotek eller för att flera enkäter svarar för " "samma bibliotek. Alternativt saknar biblioteken kommunkod eller huvudman." ).format(message, len(survey_response_ids) - num_successful_published) + logger.info(f"{log_prefix} Published {num_successful_published} survey(s); failed publishing {len(survey_response_ids) - num_successful_published} survey(s)") + else: + logger.info(f"{log_prefix} Published {num_successful_published} survey(s)") else: surveys = Survey.objects.filter(id__in=survey_response_ids) for survey in surveys.filter(_status="published"): @@ -343,6 +351,7 @@ def surveys_statuses(request): message = "Ändrade status på {} stycken enkäter.".format( len(survey_response_ids) ) + logger.info(f"{log_prefix} Changed survey.status to {status} for {len(survey_response_ids)} surveys") request.session["message"] = message return _surveys_redirect(request) diff --git a/requirements.txt b/requirements.txt index 29afa48..8b129f2 100644 --- a/requirements.txt +++ b/requirements.txt @@ -15,3 +15,4 @@ urllib3==1.26.18 certifi==2023.7.22 black==22.6.0 gunicorn==20.1.0 +python-ipware==1.0.5