broker fails on startup with "HTTPCodeError: Server returned HTTP code 0"

Bug #567515 reported by Andreas Hasenack on 2010-04-20
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Landscape Client
Critical
Thomas Herve
landscape-client (Ubuntu)
Undecided
Unassigned
Jaunty
Undecided
Unassigned
Karmic
Undecided
Unassigned
Lucid
Undecided
Unassigned

Bug Description

Etienne reported that the official landscape karmic instance he started more than 1h ago wasn't communicating with Landscape (AMI-1515F67C, us-east). I tried to start it too and got this error in the broker log, and also when starting landscape-client interactively:
2010-04-20 20:28:50,961 INFO [MainThread] Broker started on 'system' bus with config /etc/landscape/client.conf
2010-04-20 20:28:51,023 ERROR [MainThread] None
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/twisted/python/threadpool.py", line 210, in _worker
    result = context.call(ctx, function, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 59, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 37, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.6/dist-packages/landscape/lib/fetch.py", line 86, in fetch
    raise HTTPCodeError(http_code, body)
HTTPCodeError: Server returned HTTP code 0
2010-04-20 20:29:50,965 INFO [MainThread] Starting urgent message exchange with https://landscape.canonical.com/message-system.
2010-04-20 20:29:52,325 INFO [Dummy-1 ] Sent 549 bytes and received 146 bytes in 1.36s.
2010-04-20 20:29:52,328 INFO [MainThread] Switching to normal exchange mode.
2010-04-20 20:29:52,330 INFO [MainThread] Server UUID changed (old=None, new=af6f2dcf-1967-11de-8dd0-001a4b4d8d10).
2010-04-20 20:29:52,332 INFO [MainThread] Accepted types changed: +test +register +register-cloud-vm
2010-04-20 20:29:52,334 INFO [MainThread] Starting message exchange with https://landscape.canonical.com/message-system.
2010-04-20 20:29:52,334 INFO [MainThread] Message exchange completed in 1.37s.
2010-04-20 20:29:53,582 INFO [Dummy-1 ] Sent 549 bytes and received 70 bytes in 1.25s.
2010-04-20 20:29:53,587 INFO [MainThread] Message exchange completed in 1.25s.
2010-04-20 20:37:16,044 INFO [MainThread] Broker stopped on 'system' bus with config /etc/landscape/client.conf
2010-04-20 20:37:17,780 INFO [MainThread] Broker started on 'system' bus with config /etc/landscape/client.conf
2010-04-20 20:37:17,836 ERROR [MainThread] None
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/twisted/python/threadpool.py", line 210, in _worker
    result = context.call(ctx, function, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 59, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 37, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.6/dist-packages/landscape/lib/fetch.py", line 86, in fetch
    raise HTTPCodeError(http_code, body)
HTTPCodeError: Server returned HTTP code 0
2010-04-20 20:37:32,824 INFO [MainThread] Broker stopped on 'system' bus with config /etc/landscape/client.conf
2010-04-20 20:37:40,105 INFO [MainThread] Broker started on 'system' bus with config /etc/landscape/client.conf
2010-04-20 20:37:40,139 ERROR [MainThread] None
Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/twisted/python/threadpool.py", line 210, in _worker
    result = context.call(ctx, function, *args, **kwargs)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 59, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 37, in callWithContext
    return func(*args,**kw)
  File "/usr/lib/python2.6/dist-packages/landscape/lib/fetch.py", line 86, in fetch
    raise HTTPCodeError(http_code, body)
HTTPCodeError: Server returned HTTP code 0
2010-04-20 20:38:22,274 INFO [MainThread] Broker stopped on 'system' bus with config /etc/landscape/client.conf

Don't know yet what is going on. Etienne then said he started two more karmic instances, and one of them eventually worked.

Andreas Hasenack (ahasenack) wrote :

This is the user-data from that running instance which has landscape-client backtracing:
root@ip-10-242-58-193:~# curl http://169.254.169.254/1.0/user-data/;echo
ds12:exchange-urls46:https://landscape.canonical.com/message-systems4:otpsls64:X9bqtt30Ja64x6uLgiRz0VnlyCbc4nsx85k0NKW78SYdB2BxaZ4ZrcFNI8lrqr6I;s8:ping-urls35:http://landscape.canonical.com/ping;

I also tried upgrading to landscape-client 1.4.4, same error.

Changed in landscape:
importance: Undecided → Critical
milestone: none → 1.5.1
Thomas Herve (therve) wrote :

OK... I know what's going on, but I wish I don't. I tried to reproduce it a couple of times, and it seems random. For example, adding a tcpdump in parallel makes the issue disappear. Finally I added some debugging in the fetch call in Landscape, and here's what I saw returned by the EC2 API server:

2010-04-21 07:21:14: (server.c.1357) [note] sockets disabled, connection limit reached \nHTTP/1.0 200 OK\r\nContent-Type: application/octet-stream\r\nAccept-Ranges: bytes\r\nETag: "1976824587"\r\nLast-Modified: Wed, 21 Apr 2010 07:10:35 GMT\r\nContent-Length: 195\r\nConnection: close\r\nDate: Wed, 21 Apr 2010 07:21:14 GMT\r\nServer: EC2ws\r\n\r\nds12:exchange-urls46:https://landscape.canonical.com/message-systems4:otpsls64:hv1dsip9GPOCp6Qgs0kdCEQuT248rTM6IgYaX1VEDzz6ovu1I70QfqJL0eAiXFXs;s8:ping-urls35:http://landscape.canonical.com/ping;

Basically, it adds a stupid warning *in the middle of the body response*: "2010-04-21 07:21:14: (server.c.1357) [note] sockets disabled, connection limit reached \n"

I guess Amazon changed his backend to limit the number of parallel connections. Or maybe they're having high load. Of course, it's completely retarded that it appears in the middle of response.

The solution is to run those HTTP calls one by one instead of in parallel.

affects: landscape → landscape-client
Changed in landscape-client:
milestone: 1.5.1 → none
Thomas Herve (therve) on 2010-04-21
Changed in landscape-client:
assignee: nobody → Thomas Herve (therve)
milestone: none → 1.5.1
status: New → In Progress
Thomas Herve (therve) on 2010-04-22
Changed in landscape-client:
status: In Progress → Fix Committed
visibility: private → public
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package landscape-client - 1.5.0.1-0ubuntu0.10.04.0

---------------
landscape-client (1.5.0.1-0ubuntu0.10.04.0) lucid; urgency=low

  * New upstream version
    - Fix smart-update failing its very first run (LP: #562496)
    - Depend on pythonX.Y-dbus and pythonX.Y-pycurl (LP: #563063)
    - Make only one request at a time to retrieve EC2 instances (LP: #567515)
 -- Free Ekanayaka <email address hidden> Wed, 21 Apr 2010 12:31:28 +0200

Changed in landscape-client (Ubuntu Lucid):
status: New → Fix Released

Accepted landscape-client into karmic-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Changed in landscape-client (Ubuntu Karmic):
status: New → Fix Committed
tags: added: verification-needed
Changed in landscape-client (Ubuntu Jaunty):
status: New → Fix Committed
Martin Pitt (pitti) wrote :

Accepted landscape-client into jaunty-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

tags: added: needs-testing
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package landscape-client - 1.5.0.1-0ubuntu0.9.04.0

---------------
landscape-client (1.5.0.1-0ubuntu0.9.04.0) jaunty-proposed; urgency=low

  * New upstream version
    - Fix smart-update failing its very first run (LP: #562496)
    - Depend on pythonX.Y-dbus and pythonX.Y-pycurl (LP: #563063)
    - Make only one request at a time to retrieve EC2 instances (LP: #567515)

  * New upstream version (LP: #557244)
    - Fix package-changer running before smart-update has completed (LP: #542215)
    - Report the version of Eucalyptus used to generate topology data (LP: #554007)
    - Enable the Eucalyptus plugin by default, if supported (LP: #546531)
    - Use a whitelist of allowed filesystem types to instead of a blacklist (LP: #351927)
    - Report the update-manager logs to the server (LP: #503384)
    - Turn off Curl's DNS caching for requests. (LP: #522668)
 -- Free Ekanayaka <email address hidden> Wed, 21 Apr 2010 12:31:28 +0200

Changed in landscape-client (Ubuntu Jaunty):
status: Fix Committed → Fix Released
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package landscape-client - 1.5.0.1-0ubuntu0.9.10.0

---------------
landscape-client (1.5.0.1-0ubuntu0.9.10.0) karmic-proposed; urgency=low

  * New upstream version
    - Fix smart-update failing its very first run (LP: #562496)
    - Depend on pythonX.Y-dbus and pythonX.Y-pycurl (LP: #563063)
    - Make only one request at a time to retrieve EC2 instances (LP: #567515)

  * New upstream version (LP: #557244)
    - Fix package-changer running before smart-update has completed (LP: #542215)
    - Report the version of Eucalyptus used to generate topology data (LP: #554007)
    - Enable the Eucalyptus plugin by default, if supported (LP: #546531)
    - Use a whitelist of allowed filesystem types to instead of a blacklist (LP: #351927)
    - Report the update-manager logs to the server (LP: #503384)
    - Turn off Curl's DNS caching for requests. (LP: #522668)
 -- Free Ekanayaka <email address hidden> Wed, 21 Apr 2010 12:31:28 +0200

Changed in landscape-client (Ubuntu Karmic):
status: Fix Committed → Fix Released
Changed in landscape-client:
status: Fix Committed → Fix Released
tags: removed: needs-testing verification-needed

Andreas Hasenack [2010-08-23 17:38 -0000]:
> ** Tags removed: needs-testing verification-needed

Andreas, why did you remove all the v-needed tasks?

Martin

Because these packages were already released, no?

Martin Pitt <email address hidden> wrote:

>Andreas Hasenack [2010-08-23 17:38 -0000]:
>> ** Tags removed: needs-testing verification-needed
>
>Andreas, why did you remove all the v-needed tasks?
>
>Martin
>
>--
>broker fails on startup with "HTTPCodeError: Server returned HTTP code 0"
>https://bugs.launchpad.net/bugs/567515
>You received this bug notification because you are a direct subscriber
>of the bug.
>

Martin Pitt (pitti) wrote :

Andreas Hasenack [2010-08-23 22:54 -0000]:
> Because these packages were already released, no?

Ah, those were the older updates, I see. We don't usually care about
closed bug tags.

Martin
--
Martin Pitt | http://www.piware.de
Ubuntu Developer (www.ubuntu.com) | Debian Developer (www.debian.org)

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers