Multiple outgoing mentions created when connections repeatedly fail

[philgyford]

I'm not entirely clear how or why this started or continued but, from what I can tell, going back to the first instance of the error in Sentry for my website...

When sending outgoing webmentions, requests timed out and generated an error. I think this meant that the code stopped, with the new PendingOutgoingContent object created but not deleted. Then next time the script runs, it creates another PendingOutgoingContent object and tries again, and repeat. A month later I actually notice this is happening and I have 37,000 outgoing webmention statuses, mostly from this post and then more duplicates from subsequent ones!

It's possible it's related to several of the links being from my website to other posts on my site (or #anchor links to the same page (#32)) and so the server is coping with both opening outgoing connections and handling the incoming ones - maybe if something's slow it uses up its connections and so everything gets even slower, etc, etc.

Anyway. Here's the traceback from the first time it happened:

TimeoutError: [Errno 110] Connection timed out
  File "urllib3/connection.py", line 174, in _new_conn
    conn = connection.create_connection(
  File "urllib3/util/connection.py", line 95, in create_connection
    raise err
  File "urllib3/util/connection.py", line 85, in create_connection
    sock.connect(sa)
NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7f05e0f6a940>: Failed to establish a new connection: [Errno 110] Connection timed out
  File "urllib3/connectionpool.py", line 703, in urlopen
    httplib_response = self._make_request(
  File "urllib3/connectionpool.py", line 386, in _make_request
    self._validate_conn(conn)
  File "urllib3/connectionpool.py", line 1040, in _validate_conn
    conn.connect()
  File "urllib3/connection.py", line 358, in connect
    self.sock = conn = self._new_conn()
  File "urllib3/connection.py", line 186, in _new_conn
    raise NewConnectionError(
MaxRetryError: HTTPSConnectionPool(host='www.gyford.com', port=9494): Max retries exceeded with url: /webmentions/ (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f05e0f6a940>: Failed to establish a new connection: [Errno 110] Connection timed out'))
  File "requests/adapters.py", line 440, in send
    resp = conn.urlopen(
  File "urllib3/connectionpool.py", line 785, in urlopen
    retries = retries.increment(
  File "urllib3/util/retry.py", line 592, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
ConnectionError: HTTPSConnectionPool(host='www.gyford.com', port=9494): Max retries exceeded with url: /webmentions/ (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f05e0f6a940>: Failed to establish a new connection: [Errno 110] Connection timed out'))
  File "manage.py", line 22, in <module>
    execute_from_command_line(sys.argv)
  File "django/core/management/__init__.py", line 446, in execute_from_command_line
    utility.execute()
  File "django/core/management/__init__.py", line 440, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "django/core/management/base.py", line 414, in run_from_argv
    self.execute(*args, **cmd_options)
  File "django/core/management/base.py", line 460, in execute
    output = self.handle(*args, **options)
  File "mentions/management/commands/pending_mentions.py", line 28, in handle
    handle_pending_webmentions(incoming=incoming, outgoing=outgoing)
  File "mentions/tasks/scheduling.py", line 66, in handle_pending_webmentions
    process_outgoing_webmentions(wm.absolute_url, wm.text)
  File "mentions/util.py", line 46, in __call__
    return func(*args, **kwargs)
  File "mentions/tasks/outgoing_webmentions.py", line 82, in process_outgoing_webmentions
    result = _process_link(source_urlpath, link_url)
  File "mentions/tasks/outgoing_webmentions.py", line 145, in _process_link
    success, status_code = _send_webmention(source_urlpath, endpoint, link_url)
  File "mentions/tasks/outgoing_webmentions.py", line 237, in _send_webmention
    response = requests.post(endpoint, data=payload)
  File "requests/api.py", line 117, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "requests/api.py", line 61, in request
    return session.request(method=method, url=url, **kwargs)
  File "requests/sessions.py", line 529, in request
    resp = self.send(prep, **send_kwargs)
  File "requests/sessions.py", line 645, in send
    r = adapter.send(request, **kwargs)
  File "requests/adapters.py", line 519, in send
    raise ConnectionError(e, request=request)

And here's the "breadcrumbs" from Sentry (updated to correct image since I first posted this):

A couple of things that we could do:

• Looking at those breadcrumbs I'm guessing part of the problem is what seems to be nothing happening for 6-7 minutes. It looks like django-wm doesn't specify a timeout when using requests which the docs say should always be done. That would at least make failure happen more quickly. Given I was running the management command every 10 minutes (too frequently in retrospect!) the server was spending a lot of time trying to send webmentions!
• It would also be better if the code handled timeouts more gracefully. I'm not clear on the logic of the PendingOutgoingContent object, so I'm not sure what should happen to it if a connection fails, but maybe there's something to do there?

FWIW, when I've used requests in the past this is what I've done, which feels rather too laborious but I pieced it together from trying to capture all the possible failures:

def send_request(url):
    error_message = ""

    try:
        response = requests.get(url, timeout=5)
    except requests.exceptions.ConnectionError:
        error_message = "Can't connect to domain."
    except requests.exceptions.Timeout:
        error_message = "Connection timed out."
    except requests.exceptions.TooManyRedirects:
        error_message = "Too many redirects."

    try:
        response.raise_for_status()
    except requests.exceptions.HTTPError:
        # 4xx or 5xx errors:
        error_message = "HTTP Error: %s" % response.status_code
    except NameError:
        if error_message == "":
            error_message = "Something unusual went wrong."

    if error_message:
        return {"success": False, "content": error_message}
    else:
        return {"success": True, "content": response.text}

(It's also possible I'm entirely misreading what's caused this!)

[philgyford]

One other thought - should it be possible to create duplicate OutgoingWebmentionStatus objects, like it is at the moment?

Maybe ensure that source_url and target_url are unique together (unless there's some reason that would break something else that I'm missing)?

While that wouldn't fix the cause of the problem, it would prevent the symptom of thousands of identical outgoing statuses building up in the DB.

[beatonma]

Hey,

If you are upgrading to 3.0.0 be aware that the migrations will delete and recreate the PendingIncomingWebmention and PendingOutgoingContent models which will also delete any existing instances of those models. If you want to keep them please don't upgrade yet and let me know - I will add a management command to transfer them between versions.

Sorry this took such a long time to get out - especially for this particularly broken issue, but also all the others you reported. Thanks again for raising them, and for providing such detailed reports. They should all now be fixed!

[philgyford]

Wow, that's a lot of work for 3.0.0, well done! Thank you so much for all that. I should be able to try it out in the next couple of days. I don't think there's much/anything I need to keep in the pending lists, or I can recreate one or two if necessary. I'll let you know how it goes.

[philgyford]

Just wanted to say I've upgraded to 3.0.0 and things seem to be working well. Thank you so much, again!

I had to run makemigrations for the model that used MentionableMixin, due to the understandable removal of that one field, but otherwise all was smooth.

One thought for a tweak - usually an app's templates are within an app-specific directory. So, rather than the templates being in django-wm/mentions/templates/ they'd be in django-wm/mentions/templates/mentions/. Then, if the end user wants to override a template, their overriding templates would live in a templates/mentions/ directory in their project, rather than rattling around loose in templates/.

[beatonma]

Oops, just noticed your comment about the template location just now - will fix in the next release.