Bug #265

"Malformed Request" σε κάθε API call με Firefox

Added by Vangelis Koukis almost 12 years ago. Updated almost 12 years ago.

Status:Closed Start date:03/08/2011
Priority:High Due date:
Assignee:Christos Psaltis % Done:

0%

Category:Cyclades UI Spent time: -
Target version:-

Description

Με Firefox 4.0b12 προσπαθώ να ξεκινήσω ή να σταματήσω VMs και τρώω "Malformed request" με τη μία στο GUI. Με Opera παίζει κανονικά.


Related issues

duplicates Synnefo - Bug #193: πρόβλημα με τα POSTS στο django Closed 01/29/2011

History

#1 Updated by Vangelis Koukis almost 12 years ago

Αυτό μπορείτε να το δείτε με λίγο μεγαλύτερη προτεραιότητα; Δοκίμασα και Create, δεν παίζει.
Ουσιαστικά δεν φαίνεται να παίζει καμία κλήση στο API από Firefox, οπότε είμαστε λίγο δεμένοι τώρα ως προς το τι δοκιμές μπορούμε να κάνουμε.

Ενδεικτικό log από runserver:

[09/Mar/2011 04:22:33] "GET /static/pencil.png HTTP/1.1" 200 2858
[09/Mar/2011 04:22:37] "POST /api/v1.0/servers/1005/action HTTP/1.1" 400 11
[09/Mar/2011 04:22:37] "GET /static/close.png HTTP/1.1" 200 1987
[09/Mar/2011 04:22:39] "GET /machines/standard HTTP/1.1" 200 6046
[09/Mar/2011 04:22:39] "GET /api/v1.0/servers/detail HTTP/1.1" 200 3889
[09/Mar/2011 04:22:42] "GET /static/h30.png HTTP/1.1" 200 278
[09/Mar/2011 04:22:44] "POST /api/v1.0/servers HTTP/1.1" 400 11
[09/Mar/2011 04:22:46] "GET /machines/standard HTTP/1.1" 200 6046

#2 Updated by Christos Psaltis almost 12 years ago

έγινε, θα το δούμε σήμερα.

#3 Updated by Markos Gogoulos almost 12 years ago

Ίσως πρόκειται για αυτό το bug που αφορά συνδυασμό Firefox 4 beta, jQuery και Firebug? Δοκίμασε να κάνεις το παρακάτω (αν φυσικά έχεις firebug):

There is a known compatibility issue with Firebug and all current Firefox 4 betas that causes XHR callbacks to not fire. Workaround is to switch off the "Show XMLHttpRequests" option in the Console panel.

(ανοίγεις τον firebug, πατάς στο Console tab και από εκεί κάνεις switch off το "Show XMLHttpRequests"

http://bugs.jquery.com/ticket/7044
http://getfirebug.com/knownissues

#4 Updated by Constantinos Venetsanopoulos almost 12 years ago

Το ίδιο πρόβλημα έχω και εγώ με Firefox 3.6.15

#5 Updated by Christos Psaltis almost 12 years ago

Επειδή δεν έχουμε καταφέρει να αναπαράγουμε το πρόβλημα, μπορείτε να μας δώσετε κάποια στοιχεία παραπάνω για τις εκδόσεις του browser, λειτουργικό και έκδοση firebug;

Το πρόβλημα είναι μόνο στο create ή σε όλα τα post?

#6 Updated by Constantinos Venetsanopoulos almost 12 years ago

To πρόβλημα είναι σε όλα τα post. Με opera παίζει κανονικά.

Firefox 3.6.15
Firebug 1.6.2
WinXP 32bit

#7 Updated by Vangelis Koukis almost 12 years ago

Το πρόβλημα είναι σε requests create και start/stop/reboot. Για να το αναπαραγάγω:

manage.py reset db
manage.py syncdb
manage.py loaddata db/fixtures/flavors.json
manage.py loaddata db/fixtures/images.json

και μετά:

$ bin/python manage.py runserver 62.217.120.67:8000

[snip]
[10/Mar/2011 03:04:45] "GET /static/h30.png HTTP/1.1" 200 278
[10/Mar/2011 03:04:48] "POST /api/v1.0/servers HTTP/1.1" 400 11
[10/Mar/2011 03:04:48] "GET /static/close.png HTTP/1.1" 200 1987
[10/Mar/2011 03:05:40] "GET /api/v1.0/servers/detail HTTP/1.1" 200 21

Η POST /servers γυρίζει HTTP error 400.
Επίσης, κάντε το να τυπώνει το log στην έξοδο του runserver ώστε να μπορούμε να δούμε τι γίνεται.

Δοκιμάζω με Firefox 4.0b12, Windows Vista SP2, χωρίς εγκατεστημένο Firebug.

#8 Updated by Christos Psaltis almost 12 years ago

Εξακολουθώ να μην μπορώ να το αναπαράγω. Όλα τα post γίνονται κανονικά και όλες οι κλήσεις παίζουν σωστά.

Δοκίμασα firefox 3.6.15, firebug 1.6.2 σε windows 7 (64bit) και firefox 4b12, χωρίς firebug σε windows 7 (64bit). Δυστυχώς δεν έχουμε κάποιο μηχάνημα με XP.

Είχατε το ίδιο πρόβλημα σε άλλα λειτουργικά;

Ακουλουθεί αποτέλεσμα από το δεύτερο setup δοκιμών στο list view:

[10/Mar/2011 04:01:54] "GET /api/v1.0/servers/detail HTTP/1.1" 200 1182
[10/Mar/2011 04:01:54] "GET /static/asc.gif HTTP/1.1" 200 54
[10/Mar/2011 04:01:54] "GET /static/bg.gif HTTP/1.1" 200 64
[10/Mar/2011 04:02:49] "POST /api/v1.0/servers/7/action HTTP/1.1" 202 0
[10/Mar/2011 04:02:51] "GET /api/v1.0/servers/detail HTTP/1.1" 200 1182
[10/Mar/2011 04:02:52] "POST /api/v1.0/servers/6/action HTTP/1.1" 202 0
[10/Mar/2011 04:02:52] "GET /static/close.png HTTP/1.1" 200 1987
[10/Mar/2011 04:03:08] "GET /machines/list HTTP/1.1" 200 10262

#9 Updated by Vangelis Koukis almost 12 years ago

Τότε, κάντε το να βγάζει πλήρες log στο output του runserver ώστε να μπορέσουμε να πάρουμε πίσω debugging trace και να δούμε πού ακριβώς σκάει.
Ή να μπορεί να μπει μια εντολή που να εκτυπώνει το πλήρες κείμενο του request που για κάποιο λόγο βγαίνει malformed.

#10 Updated by Markos Gogoulos almost 12 years ago

Στο output του runserver βγάζει και το error και το exception, μέσω της log.exception που έχει μπει στα (except Exception) blocks.

Το 400 error απο POST το δίνει μόνο η create server και συγκεκριμένα μονο αυτό

        except Exception as e:
            log.exception('Malformed create request: %s - %s' % (e, request.raw_post_data))    
            raise fault.badRequest

Οπότε θα έπρεπε να σου βγάζει το log. Έχεις κάνει git pull?

#11 Updated by Vangelis Koukis almost 12 years ago

Κάνω τα εξής:

devel@store67:~/synnefo$ git pull
Already up-to-date.
devel@store67:~/synnefo$ bin/python manage.py runserver 62.217.120.67:8000
Validating models...
0 errors found
Django version 1.2.4, using settings 'synnefo.settings'
Development server is running at http://62.217.120.67:8000/
Quit the server with CONTROL-C.
[10/Mar/2011 05:16:20] "GET / HTTP/1.1" 200 19819
[10/Mar/2011 05:16:20] "GET /static/jquery.tools.min.js HTTP/1.1" 200 118700
[10/Mar/2011 05:16:20] "GET /static/jquery.cookie.js HTTP/1.1" 200 3713
[10/Mar/2011 05:16:20] "GET /static/jQueryRotate.js HTTP/1.1" 200 13604
[10/Mar/2011 05:16:20] "GET /static/jquery.dataTables.min.js HTTP/1.1" 200 66539
[10/Mar/2011 05:16:20] "GET /static/synnefo.js HTTP/1.1" 200 13114
[10/Mar/2011 05:16:20] "GET /static/main.css HTTP/1.1" 200 16107
[10/Mar/2011 05:16:20] "GET /static/nefo.png HTTP/1.1" 200 2236
[10/Mar/2011 05:16:21] "GET /static/degrade-background.png HTTP/1.1" 200 318
[10/Mar/2011 05:16:21] "GET /api/v1.0/images/detail HTTP/1.1" 200 1113
[10/Mar/2011 05:16:21] "GET /api/v1.0/flavors/detail HTTP/1.1" 200 4119
[10/Mar/2011 05:16:21] "GET /machines HTTP/1.1" 200 13317
[10/Mar/2011 05:16:21] "GET / HTTP/1.1" 200 19819
[10/Mar/2011 05:16:21] "GET /static/arrow.png HTTP/1.1" 200 348
[10/Mar/2011 05:16:21] "GET /api/v1.0/images/detail HTTP/1.1" 200 1113
[10/Mar/2011 05:16:21] "GET /api/v1.0/flavors/detail HTTP/1.1" 200 4119
[10/Mar/2011 05:16:21] "GET /machines/standard HTTP/1.1" 200 6103
[10/Mar/2011 05:16:21] "GET /static/os_logos/debian.png HTTP/1.1" 200 1127
[10/Mar/2011 05:16:21] "GET /static/os_logos/freebsd.png HTTP/1.1" 200 1756
[10/Mar/2011 05:16:21] "GET /static/os_logos/gentoo.png HTTP/1.1" 200 1927
[10/Mar/2011 05:16:21] "GET /api/v1.0/servers/detail HTTP/1.1" 200 21
[10/Mar/2011 05:16:21] "GET /static/progress.gif HTTP/1.1" 200 2608
[10/Mar/2011 05:16:22] "GET /static/h30.png HTTP/1.1" 200 278
[10/Mar/2011 05:16:29] "POST /api/v1.0/servers HTTP/1.1" 400 11

Έχω κάνει git pull, το τελευταίο commit που βλέπω είναι το f15025bcd8fa106bb79b6c2cf322475302936573.
Τρέχω runserver όπως φαίνεται στα παραπάνω, και όταν σκάει η POST 400 δεν βλέπω τίποτε στην έξοδο.
Άρα δεν εμφανίζεται το output της log.

Μπορείς να μου στείλεις ακριβώς πώς κάνεις runserver ώστε να βλέπεις το output του logging;

#12 Updated by Markos Gogoulos almost 12 years ago

όπου έχει log.exception θα πρέπει να σου βγάζει στο runserver το error. Πχ:

ERROR:synnefo.api.handlers:Unexpected error: Flavor matching query does not exist.
Traceback (most recent call last):
  File "/home/user/Desktop/unweb/synnefo/../synnefo/api/handlers.py", line 148, in read_all
    } for server in virtual_servers]
  File "/home/user/Desktop/unweb/synnefo/lib/python2.6/site-packages/django/db/models/fields/related.py", line 313, in __get__
    rel_obj = QuerySet(self.field.rel.to).using(db).get(**params)
  File "/home/user/Desktop/unweb/synnefo/lib/python2.6/site-packages/django/db/models/query.py", line 347, in get
    % self.model._meta.object_name)
DoesNotExist: Flavor matching query does not exist.
[10/Mar/2011 05:50:57] "GET /api/v1.0/servers/detail HTTP/1.1" 503 124

Αν δεν στα βγάζει στο runserver ενδεχομένως έχει να κάνει με τον logger και τη συμπεριφορά του στα windows? Μπορείς να ορίσεις το logger να γράφει σε αρχείο ώστε να είσαι σίγουρος οτι καταγράφει αν για κάποιο λόγο δεν μπορεί να τα δείξει στο output

Κατα τ'άλλα στην ServerHandler.create αν μπορείς βάλε πριν το try... import pdb; pdb.set_trace() και δοκίμασε να δεις γιατι αποτυγχάνει το create, τι στέλνει λάθος.

Σε τι λειτουργικό/browser δοκιμάζεις?

#13 Updated by Vangelis Koukis almost 12 years ago

Markos Gogoulos wrote:

όπου έχει log.exception θα πρέπει να σου βγάζει στο runserver το error. Πχ:

[...]

Μάρκο, το καταλαβαίνω αυτό, αλλά όταν εγώ τρέχω runserver δεν βλέπω αυτό το output.
Μπορείς να μου στείλεις την ακριβή εντολή που τρέχεις στο σύστημα σου όταν τρέχεις το manage.py runserver και σου βγάζει το output των loggers στο standard error του runserver?

Αν δεν στα βγάζει στο runserver ενδεχομένως έχει να κάνει με τον logger και τη συμπεριφορά του στα windows? Μπορείς να ορίσεις το logger να γράφει σε αρχείο ώστε να είσαι σίγουρος οτι καταγράφει αν για κάποιο λόγο δεν μπορεί να τα δείξει στο output

Δεν έχει καμία σχέση με τα Windows αυτό. Δεν τρέχω το synnefo σε περιβάλλον Windows, το τρέχω σε Debian. Εκεί κάνω runserver, με python από το virtualenv σύμφωνα με το README που συντηρούμε.

Κατα τ'άλλα στην ServerHandler.create αν μπορείς βάλε πριν το try... import pdb; pdb.set_trace() και δοκίμασε να δεις γιατι αποτυγχάνει το create, τι στέλνει λάθος.

Θα το κάνω αυτό, αλλά στείλε ακριβώς πώς τρέχεις το runserver κι έχεις τέτοιου είδους output.

Σε τι λειτουργικό/browser δοκιμάζεις?

Εδώ έχω στείλει ακριβώς πώς μπορώ αν το αναπαραγάγω: https://code.grnet.gr/issues/265#note-7

Καλή συνέχεια,
Βαγγέλης

#14 Updated by Vangelis Koukis almost 12 years ago

Τα τελευταία δεδομένα για αυτό:

α) Δεν είναι θέμα logging. Ο λόγος που δεν loggάρεται τίποτε, είναι γιατί ποτέ δεν φτάνει καν στην ανάλογη μέθοδο.
Το HTTP 400 [bad request] το τρώει από πριν.

β) Το 400 δεν προέρχεται από το σημείο που αναφέρει ο Μάρκος παραπάνω στα σχόλια. Το άλλαξα σε serviceUnavailable και συνεχίζει να επιστρέφει 400.

γ) Έβαλα print στο sys.stderr στην αρχή της read_all() και βγάζει πράγματα στην κονσόλα.
δ) Έβαλα print στο sys.stderr στην αρχή της μεθόδου και δεν βγάζει τίποτε στην κονσόλα.

Οπότε, υπάρχει θέμα με το request, δεν φτάνει καν στην ανάλογη μέθοδο.
Κάποιος επιστρέφει 400 νωρίτερα.

#15 Updated by Vangelis Koukis almost 12 years ago

Vangelis Koukis wrote:

Οπότε, υπάρχει θέμα με το request, δεν φτάνει καν στην ανάλογη μέθοδο.
Κάποιος επιστρέφει 400 νωρίτερα.

Λοιπόν, μπορώ να το αναπαραγάγω σε κάθε περίπτωση, χωρίς τον Firefox.
Έστω τα εξής δύο requests:

REQUEST 1:

  POST /api/v1.0/servers HTTP/1.1
  Host: 62.217.120.67:8000
  User-Agent: Mozilla/5.0 (Windows NT 6.0; rv:2.0) Gecko/20100101 Firefox/4.0
  Accept: application/json, text/javascript, */*
  Accept-Language: en-us,en;q=0.5
  Accept-Encoding: gzip, deflate
  Accept-Charset: ISO-8859-7,utf-8;q=0.7,*;q=0.7
  Keep-Alive: 115
  Connection: keep-alive
  Content-Type: application/x-www-form-urlencoded; charset=UTF-8
  X-Requested-With: XMLHttpRequest
  Referer: http://62.217.120.67:8000/
  Content-Length: 132
  Cookie: list=0
  Pragma: no-cache
  Cache-Control: no-cache

  {"server":{"name":"My Debian Unstable server","imageId":"3","flavorId":1,"metadata":{"My Server Name":"My Debian Unstable server"}}}

REQUEST 2:
  POST /api/v1.0/servers HTTP/1.1
  User-Agent: Opera/9.80 (Windows NT 6.0; U; en) Presto/2.7.62 Version/11.01
  Host: 62.217.120.67:8000
  Accept-Language: en,el-GR;q=0.9,el;q=0.8
  Accept-Charset: iso-8859-1, utf-8, utf-16, *;q=0.1
  Accept-Encoding: deflate, gzip, x-gzip, identity, *;q=0
  Referer: http://62.217.120.67:8000/
  Cookie: list=0
  Cookie2: $Version=1
  Connection: Keep-Alive, TE
  TE: deflate, gzip, chunked, identity, trailers
  Content-Length: 132
  Content-Type: application/x-www-form-urlencoded
  X-Requested-With: XMLHttpRequest
  Accept: application/json, text/javascript, */*
  Content-Transfer-Encoding: binary

  {"server":{"name":"My Debian Unstable server","imageId":"3","flavorId":1,"metadata":{"My Server Name":"My Debian Unstable server"}}}

Το πρώτο είναι από τον Firefox, το δεύτερο από τον Opera.
Το πρώτο επιστρέφει πάντα 400 Bad request κι η αίτηση δεν φαίνεται να φτάνει στην create() method, το δεύτερο παίζει κανονικά.
Παρακαλώ επιβεβαιώστε ότι μπορείτε να αναπαραγάγετε το πρόβλημα.

#16 Updated by Vangelis Koukis almost 12 years ago

Το πρόβλημα είναι το header Content-Type: application/x-www-form-urlencoded; charset=UTF-8 που περνάει o Firefox σε αντίθεση με τον Opera.

Αυτό χτυπάει στο συγκεκριμένο θέμα με το Piston:
https://bitbucket.org/jespern/django-piston/issue/99/bad-request-and-content-type-with-fix

Με εφαρμογή της αλλαγής που προτείνεται με το χέρι, δούλεψε.

α) γιατί δεν μπορούσατε να replicate το bug; ποια έκδοση του Piston τρέχετε;
β) μπορείτε να θέσετε με το χέρι στο GUI το Content-Type ώστε να μην πνίγεται το Piston; απ'ό,τι βλέπω αυτό υποστηρίζεται από τη jQuery.

ΥΓ. Τώρα βλέπω ότι αυτό έχει ήδη διορθωθεί! στο #193 και υπάρχουν ανάμεσα σε άλλα οδηγίες στο README, αλλά δεν θυμάμαι ούτε να το συζητήσαμε ποτέ από κοντά, ούτε να είχε σταλεί ειδικό μέηλ που να προτρέπει για την αλλαγή. Επίσης, το #193 το έφτιαξε ο Μάρκος, με watcher το Χρίστο. Οπότε, ΓΙΑΤΙ ΨΑΧΝΟΥΜΕ ΔΥΟ ΜΕΡΕΣ ΤΩΡΑ κάτι που ήταν ήδη γνωστό; Κι επίσης, μήπως θα έπρεπε να είχε τονιστεί ΠΟΛΥ ΠΕΡΙΣΣΟΤΕΡΟ κάτι που χρειάζεται patching του software που πρόκειται να τρέξουμε;

#17 Updated by Vangelis Koukis almost 12 years ago

  • Status changed from Assigned to Closed

Also available in: Atom PDF