Double submitting to callback?

[James Westby]

[2012-02-29 18:09:26,199: INFO/MainProcess] Got task from broker: djpkgme.tasks.BuildPackageTask[994b998d-bae7-488d-81a8-71b1b3b864df]
[2012-02-29 18:09:26,200: INFO/PoolWorker-1] djpkgme.tasks.BuildPackageTask[994b998d-bae7-488d-81a8-71b1b3b864df]: Building package for 42: http://localhost:58043/jabberwocky.pdf
[2012-02-29 18:09:28,438: INFO/PoolWorker-1] djpkgme.tasks.BuildPackageTask[994b998d-bae7-488d-81a8-71b1b3b864df]: Submitting success info to u'http://localhost:58043/callback': http://ec2-107-21-65-245.compute-1.amazonaws.com/+output/jabberwocky-1.tar.gz
[2012-02-29 18:09:28,493: ERROR/MainProcess] Task djpkgme.tasks.BuildPackageTask[994b998d-bae7-488d-81a8-71b1b3b864df] raised exception: error(111, 'Connection refused')
Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.6/celery/execute/trace.py", line 47, in trace
    return cls(states.SUCCESS, retval=fun(*args, **kwargs))
  File "/usr/lib/pymodules/python2.6/celery/app/task/__init__.py", line 247, in __call__
    return self.run(*args, **kwargs)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 378, in run
    submit_pkgme_info(packaged_app_url, metadata)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 101, in submit_pkgme_info
    return submit_to_myapps(metadata['callback_url'], body)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 94, in submit_to_myapps
    url, method='PUT', headers=headers, body=json_body)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1444, in request
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1196, in _request
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1170, in _conn_request
    conn.connect()
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 798, in connect
    raise socket.error, msg
error: [Errno 111] Connection refused
Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.6/celery/execute/trace.py", line 47, in trace
    return cls(states.SUCCESS, retval=fun(*args, **kwargs))
  File "/usr/lib/pymodules/python2.6/celery/app/task/__init__.py", line 247, in __call__
    return self.run(*args, **kwargs)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 378, in run
    submit_pkgme_info(packaged_app_url, metadata)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 101, in submit_pkgme_info
    return submit_to_myapps(metadata['callback_url'], body)
  File "/home/ubuntu/pkgme-service/sourcecode/../src/djpkgme/tasks.py", line 94, in submit_to_myapps
    url, method='PUT', headers=headers, body=json_body)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1444, in request
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1196, in _request
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 1170, in _conn_request
    conn.connect()
  File "/usr/lib/pymodules/python2.6/httplib2/__init__.py", line 798, in connect
    raise socket.error, msg
error: [Errno 111] Connection refused

Trying current trunk on ec2. The harness successfully shows the callback info, so it looks
like this is failing because it is sending the callback twice?

Thanks,

James

[Jonathan Lange (jml)]

I don't think so. If you change the harness so that it doesn't shut down when it gets a response, you'll see that only one request is ever sent to it. I think the problem is that we are shutting down the service too early.

From #twisted.web on 2012-01-12:

jml: When is Resource.render() called?
exarkun: When a Resource is found to service a request
jml: is the request fully received by that point?
exarkun: Yes
jml: OK, thanks.
jml: I have a Resource locally that waits for one request and then shuts down the web server. However, the other end is reporting a connection refused after sending the request. I can't figure out what this second attempted connection is all about.
exarkun: favicon? :)
exarkun: You may also be shutting down the reactor such that the response is never sent, and some kind of retry logic in the client is kicking in.
jml: exarkun: ooh, that last one might be it.
jml: exarkun: is there an event I can hook into to ensure the response has been sent?
exarkun: :(
exarkun: not as far as I know
jml: exarkun: how vexing.
jml: I'm currently starting the shutdown on notifyFinish
exarkun: Yea, you'd sorta expect that to be good enough.
jml: I'll try a callLater to verify that this is indeed what's happening.
jml: reactor.callLater(0, ...) to the rescue :(

[James Westby (james-w)]

On Mon, 05 Mar 2012 16:30:42 -0000, Jonathan Lange <email address hidden> wrote:
> I don't think so. If you change the harness so that it doesn't shut
> down when it gets a response, you'll see that only one request is ever
> sent to it. I think the problem is that we are shutting down the service
> too early.
>
> >From #twisted.web on 2012-01-12:
>
> jml: When is Resource.render() called?
> exarkun: When a Resource is found to service a request
> jml: is the request fully received by that point?
> exarkun: Yes
> jml: OK, thanks.
> jml: I have a Resource locally that waits for one request and then shuts down the web server. However, the other end is reporting a connection refused after sending the request. I can't figure out what this second attempted connection is all about.
> exarkun: favicon? :)
> exarkun: You may also be shutting down the reactor such that the response is never sent, and some kind of retry logic in the client is kicking in.
> jml: exarkun: ooh, that last one might be it.
> jml: exarkun: is there an event I can hook into to ensure the response has been sent?
> exarkun: :(
> exarkun: not as far as I know
> jml: exarkun: how vexing.
> jml: I'm currently starting the shutdown on notifyFinish
> exarkun: Yea, you'd sorta expect that to be good enough.
> jml: I'll try a callLater to verify that this is indeed what's happening.
> jml: reactor.callLater(0, ...) to the rescue :(

That's the code we have right? So it seems that callLater isn't enough
to make sure that the response is sent before the reactor shuts down?

Thanks,

James

[Jonathan Lange (jml)]

On Tue, Mar 6, 2012 at 2:01 AM, James Westby <email address hidden> wrote:
> On Mon, 05 Mar 2012 16:30:42 -0000, Jonathan Lange <email address hidden> wrote:
>> I don't think so.  If you change the harness so that it doesn't shut
>> down when it gets a response, you'll see that only one request is ever
>> sent to it. I think the problem is that we are shutting down the service
>> too early.
>>
>> >From #twisted.web on 2012-01-12:
>>
>> jml: When is Resource.render() called?
>> exarkun: When a Resource is found to service a request
>> jml: is the request fully received by that point?
>> exarkun: Yes
>> jml: OK, thanks.
>> jml: I have a Resource locally that waits for one request and then shuts down the web server. However, the other end is reporting a connection refused after sending the request. I can't figure out what this second attempted connection is all about.
>> exarkun: favicon? :)
>> exarkun: You may also be shutting down the reactor such that the response is never sent, and some kind of retry logic in the client is kicking in.
>> jml: exarkun: ooh, that last one might be it.
>> jml: exarkun: is there an event I can hook into to ensure the response has been sent?
>> exarkun: :(
>> exarkun: not as far as I know
>> jml: exarkun: how vexing.
>> jml: I'm currently starting the shutdown on notifyFinish
>> exarkun: Yea, you'd sorta expect that to be good enough.
>> jml: I'll try a callLater to verify that this is indeed what's happening.
>> jml: reactor.callLater(0, ...) to the rescue :(
>
> That's the code we have right? So it seems that callLater isn't enough
> to make sure that the response is sent before the reactor shuts down?
>

Yeah, that's correct. My guess is that it's a cheap hack that doesn't work.

Probably the right thing to do here is file a bug on Twisted. I'll do that now.

jml

[Jonathan Lange (jml)]

Wow. Producing a minimal example took a long time.

[James Westby (james-w)]

A workaround has landed in our tree.

Thanks,

James