approvals: use logging instead of stdout in send_approvals_to_pe

This will ease the monitoring

itou/approvals/management/commands/send_approvals_to_pe.py

@@ -62,12 +62,15 @@ def handle(self, *, wet_run, delay, **options):
         ).order_by("-start_at")
 
         nb_approvals = queryset.count()
-        self.stdout.write(f"approvals needing to be sent count={nb_approvals}, batch count={MAX_APPROVALS_PER_RUN}")
+        self.logger.info("approvals needing to be sent count=%s, batch count=%s", nb_approvals, MAX_APPROVALS_PER_RUN)
         nb_approvals_to_send = min(nb_approvals, MAX_APPROVALS_PER_RUN)
 
         for approval in queryset[:nb_approvals_to_send]:
-            self.stdout.write(
-                f"approvals={approval} start_at={approval.start_at} pe_state={approval.pe_notification_status}"
+            self.logger.info(
+                "approvals=%s start_at=%s pe_state=%s",
+                approval,
+                approval.start_at,
+                approval.pe_notification_status,
             )
             if wet_run:
                 approval.notify_pole_emploi()
@@ -81,13 +84,17 @@ def handle(self, *, wet_run, delay, **options):
                 api_enums.PEApiNotificationStatus.SHOULD_RETRY,
             ],
         ).order_by("-start_at")
-        self.stdout.write(
-            f"cancelled approvals needing to be sent count={cancelled_queryset.count()}, batch count={batch_left}"
+        self.logger.info(
+            "cancelled approvals needing to be sent count=%s, batch count=%s",
+            cancelled_queryset.count(),
+            batch_left,
         )
         for cancelled_approval in cancelled_queryset[:batch_left]:
-            self.stdout.write(
-                f"cancelled_approval={cancelled_approval} start_at={cancelled_approval.start_at} "
-                f"pe_state={cancelled_approval.pe_notification_status}"
+            self.logger.info(
+                "cancelled_approval=%s start_at=%s pe_state=%s",
+                cancelled_approval,
+                cancelled_approval.start_at,
+                cancelled_approval.pe_notification_status,
             )
             if wet_run:
                 cancelled_approval.notify_pole_emploi()

tests/approvals/test_notify_pole_emploi.py

@@ -1,5 +1,4 @@
 import datetime
-import io
 import json
 from unittest.mock import patch
 
@@ -556,8 +555,7 @@ class TestApprovalsSendToPeManagement:
     @patch("itou.approvals.management.commands.send_approvals_to_pe.sleep")
     # smaller batch to ease testing
     @patch("itou.approvals.management.commands.send_approvals_to_pe.MAX_APPROVALS_PER_RUN", 10)
-    def test_invalid_job_seeker_for_pole_emploi(self, sleep_mock, notify_mock, cancelled_notify_mock):
-        stdout = io.StringIO()
+    def test_invalid_job_seeker_for_pole_emploi(self, sleep_mock, notify_mock, cancelled_notify_mock, caplog):
         # create ignored Approvals, will not even be counted in the batch. the cron will wait for
         # the database to have the necessary job application, nir, or start date to fetch them.
         no_jobapp = ApprovalFactory(with_jobapplication=False)
@@ -598,9 +596,8 @@ def test_invalid_job_seeker_for_pole_emploi(self, sleep_mock, notify_mock, cance
             "send_approvals_to_pe",
             wet_run=True,
             delay=3,
-            stdout=stdout,
         )
-        assert stdout.getvalue().split("\n") == [
+        assert caplog.messages[:-1] == [
             "approvals needing to be sent count=3, batch count=10",
             f"approvals={pending_approval} start_at={pending_approval.start_at.isoformat()} "
             "pe_state=notification_ready",
@@ -613,9 +610,11 @@ def test_invalid_job_seeker_for_pole_emploi(self, sleep_mock, notify_mock, cance
             f"cancelled_approval={cancelled_approval} start_at={cancelled_approval.start_at.isoformat()} "
             "pe_state=notification_ready"
             for cancelled_approval in cancelled_approvals[:7]
-        ] + [
-            "",
         ]
+        # Last log shows the timing: use startswith
+        assert caplog.messages[-1].startswith(
+            "Management command itou.approvals.management.commands.send_approvals_to_pe succeeded in "
+        )
         sleep_mock.assert_called_with(3)
         assert sleep_mock.call_count == 10
         assert notify_mock.call_count == 3