Random crash when sending many notifications

[aaugustin]

I'm sending batches of ~1 million notifications. I need to send them fairly quickly, so I'm spreading the work to 10 distinct Python processes (not threads) with the multiprocessing module. Each process passes an iterator of ~100k tokens to send_notification_batch.

This used to work very well, but since a few days, I'm getting this exception:

Traceback (most recent call last):
  File "/home/ubuntu/myapp/src/myapp/apns.py", line 149, in _send_many
    topic=settings.APNS_TOPIC,
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/apns2/client.py", line 174, in send_notification_batch
    priority, expiration, collapse_id)
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/apns2/client.py", line 120, in send_notification_async
    stream_id = self._connection.request('POST', url, json_payload, headers)  # type: int
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/src/hyper/hyper/http20/connection.py", line 274, in request
    self.endheaders(message_body=body, final=True, stream_id=stream_id)
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/src/hyper/hyper/http20/connection.py", line 571, in endheaders
    stream.send_headers(headers_only)
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/src/hyper/hyper/http20/stream.py", line 98, in send_headers
    conn.send_headers(self.stream_id, headers, end_stream)
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/connection.py", line 844, in send_headers
    headers, self.encoder, end_stream
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/stream.py", line 913, in send_headers
    headers, encoder, hf, hdr_validation_flags
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/stream.py", line 1306, in _build_headers_frames
    encoded_headers = encoder.encode(headers)
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/hpack/hpack.py", line 249, in encode
    for header in headers:
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/utilities.py", line 474, in inner
    for header in headers:
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/utilities.py", line 419, in _validate_host_authority_header
    for header in headers:
  File "/home/ubuntu/.pyenv/versions/3.6.2/envs/myapp/lib/python3.6/site-packages/h2/utilities.py", line 331, in _reject_pseudo_header_fields
    "Received duplicate pseudo-header field %s" % header[0]
h2.exceptions.ProtocolError: Received duplicate pseudo-header field b':path'

I think it's random. I haven't been able to reproduce it at a small scale. I haven't been able to figure out with what frequency it happens yet.

I couldn't track down a change in a library that would cause this. It didn't start with a code deployment.

Here are the versions I'm using:

apns2 = 0.6.0
hyper = https://github.com/Lukasa/hyper.git@18b629b8487169870235fe13387e2ae03c178b9f
h2 = 2.6.2

---

The exception happens when we're preparing a request to send to APNS. If there's a bug, it's likely in hyper or h2, but hyper has been dead for 2 years, so there's no point filing a bug there.

I'm not sure there's much you can do with the information I provided :-( I'm writing the bug report in case someone else has the same issue, mostly...

In the long run, I guess it will be best to switch to httpx, but I'm not sure it does what you need yet — namely encode/httpx#52

---

For now, I added debug code to try to figure out what happens:

--- apns2/client.py  2019-10-12 08:43:14.000000000 +0200
+++ apns2/client.py   2019-10-12 08:42:21.000000000 +0200
@@ -117,7 +117,13 @@
             headers['apns-collapse-id'] = collapse_id

         url = '/3/device/{}'.format(token_hex)
-        stream_id = self._connection.request('POST', url, json_payload, headers)  # type: int
+        try:
+            stream_id = self._connection.request('POST', url, json_payload, headers)  # type: int
+        except Exception:
+            from myapp import logging as m_logging
+            m_logger = m_logging.get_logger("apns2.debug")
+            m_logger.exception("Exception in send_notification_async", code="apns2.send_notification_async", url=url, json_payload=json_payload, headers=headers)
+            raise
         return stream_id

     def get_notification_result(self, stream_id: int) -> Union[str, Tuple[str, str]]:
@@ -170,8 +176,11 @@
             self.update_max_concurrent_streams()
             if next_notification is not None and len(open_streams) < self.__max_concurrent_streams:
                 logger.info('Sending to token %s', next_notification.token)
-                stream_id = self.send_notification_async(next_notification.token, next_notification.payload, topic,
-                                                         priority, expiration, collapse_id)
+                try:
+                    stream_id = self.send_notification_async(next_notification.token, next_notification.payload, topic,
+                                                             priority, expiration, collapse_id)
+                except Exception:
+                    results[next_notification.token] = 'Failed'
                 open_streams.append(RequestStream(stream_id, next_notification.token))

                 next_notification = next(notification_iterator, None)

I can't send a notification to 1 million people just for testing, though, so debugging will take time...

[aaugustin]

OK, this happens if a token has an invalid values.

Most of my tokens are 64 bytes hexadecimal values, like they should, but a few looked like this: '{length=32,bytes=0x17b5a6fa9dbac4141edc5325e38e4087...baa709c0916f3bc0}' — probably a bug in the upstream system from which I get tokens.

Perhaps the library could crash with a less obscure exception, in case this happens to anyone else?

[Negaihoshi]

This issue is probably iOS 13 related issue.
https://forums.developer.apple.com/thread/117545