Django admin upload media to FTP on Heroku

I am uploading static images from admin to my ftp.
However, I am having an issue that causes Heroku H12 error.

I am using uwsgi. MY uwsgi.ini file is below

[uwsgi]
http-socket = :$(PORT)
master = true
processes = 4
die-on-term = true
module = project.wsgi
memory-report = true

The model on_save has been overridden to create thumbnail and save it. I am using django-storages for ftp upload. Below is the overridden code

def save(self, *args, **kwargs):
    start=datetime.datetime.now()
    print "starting save in admin.save", start
    update_image = True
    if self.id: # if updating record, then check if image path has changed
        update_image = False
        orig = VenueMedia.objects.get(id=self.id)
        if self.url != orig.url:
            update_image = True

    print "in save in admin.save, seconds passed=", (datetime.datetime.now()-start).seconds
    if update_image:
        print "in update_image in admin.save, seconds passed=", (datetime.datetime.now()-start).seconds
        image = Img.open(StringIO.StringIO(self.url.read()))
        orignal_ratio = float(image.size[0])/image.size[1]
        new_height = int(round(orignal_ratio * 171))
        image.thumbnail((new_height,171), Img.ANTIALIAS)
        output = StringIO.StringIO()
        image.save(output, format='JPEG', quality=75)
        output.seek(0)
        self.thumbnail_url = InMemoryUploadedFile(output, 'ImageField', "%s" % str(self.url.name), 'image/jpeg', output.len, None)

        if not self.venueid.thumb_image_path:
            self.venueid.thumb_image_path = self.thumbnail_url
            self.venueid.save()
    print "before calling django.save in admin.save, seconds passed=", (datetime.datetime.now()-start).seconds
    super(VenueMedia, self).save(*args, **kwargs)
    print "after calling django.save in admin.save, seconds passed= ",(datetime.datetime.now()-start).seconds

Now when I try to upload photos –

2015-10-10T08:03:37.436433+00:00 app[web.1]: {address space usage: 523321344 bytes/499MB} {rss usage: 62889984 bytes/59MB} [pid: 10|app: 0|req: 87/583] 10.13.196.21 () {52 vars in 1048 bytes} [Sat Oct 10 08:03:37 2015] GET /admin/jsi18n/ => generated 2372 bytes in 82 msecs (HTTP/1.1 200) 3 headers in 93 bytes (1 switches on core 0)
2015-10-10T08:04:21.574828+00:00 app[web.1]: starting save in admin.save 2015-10-10 08:04:21.574740
2015-10-10T08:04:21.574837+00:00 app[web.1]: in save in admin.save, seconds passed= 0
2015-10-10T08:04:21.574839+00:00 app[web.1]: in update_image in admin.save, seconds passed= 0
2015-10-10T08:04:21.662097+00:00 app[web.1]: before calling django.save in admin.save, seconds passed= 0
2015-10-10T08:04:50.772264+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/admin/website/venue/1882/?_changelist_filters=o%3D6.-4" host=www.speedyvenues.com request_id=2646454f-177b-4aa5-9b88-1bfb4cbc4af7 fwd="116.203.74.26" dyno=web.1 connect=1ms service=33270ms status=503 bytes=0
2015-10-10T08:04:59.857662+00:00 heroku[router]: at=info method=GET path="/admin/website/venue/1882/" host=www.speedyvenues.com request_id=8a966f9e-cfda-4f0f-b4c3-db42a29af53b fwd="116.203.74.26" dyno=web.1 connect=1ms service=1575ms status=200 bytes=193332
2015-10-10T08:04:59.855573+00:00 app[web.1]: {address space usage: 532455424 bytes/507MB} {rss usage: 72032256 bytes/68MB} [pid: 11|app: 0|req: 172/584] 10.45.79.55 () {52 vars in 1079 bytes} [Sat Oct 10 08:04:58 2015] GET /admin/website/venue/1882/ => generated 192996 bytes in 1569 msecs (HTTP/1.1 200) 7 headers in 336 bytes (2 switches on core 0)
2015-10-10T08:05:00.427746+00:00 heroku[router]: at=info method=GET path="/admin/jsi18n/" host=www.speedyvenues.com request_id=774ec812-f06e-4900-8a16-3c26f959d234 fwd="116.203.74.26" dyno=web.1 connect=1ms service=64ms status=200 bytes=2465
2015-10-10T08:05:00.426008+00:00 app[web.1]: {address space usage: 523321344 bytes/499MB} {rss usage: 62889984 bytes/59MB} [pid: 10|app: 0|req: 88/585] 10.31.102.73 () {52 vars in 1019 bytes} [Sat Oct 10 08:05:00 2015] GET /admin/jsi18n/ => generated 2372 bytes in 60 msecs (HTTP/1.1 200) 3 headers in 93 bytes (1 switches on core 0)
2015-10-10T08:05:53.065785+00:00 app[web.1]: after calling django.save in admin.save, seconds passed= 91
2015-10-10T08:05:53.146692+00:00 app[web.1]: before calling django.save in admin.save, seconds passed= 0
2015-10-10T08:05:53.089162+00:00 app[web.1]: starting save in admin.save 2015-10-10 08:05:53.089063
2015-10-10T08:05:53.089175+00:00 app[web.1]: in save in admin.save, seconds passed= 0
2015-10-10T08:05:53.089178+00:00 app[web.1]: in update_image in admin.save, seconds passed= 0
2015-10-10T08:05:53.132219+00:00 app[web.1]: {address space usage: 529453056 bytes/504MB} {rss usage: 68853760 bytes/65MB} [pid: 12|app: 0|req: 288/586] 10.138.91.199 () {62 vars in 1412 bytes} [Sat Oct 10 08:04:17 2015] POST /admin/website/venue/1882/?_changelist_filters=o%3D6.-4 => generated 0 bytes in 95630 msecs (HTTP/1.1 302) 8 headers in 519 bytes (245 switches on core 0)
2015-10-10T08:06:05.673451+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/admin/website/venue/1882/" host=www.speedyvenues.com request_id=40827838-f116-43a6-ad39-5fa39429d04e fwd="116.203.74.26" dyno=web.1 connect=1ms service=33300ms status=503 bytes=0
2015-10-10T08:06:38.872790+00:00 heroku[router]: at=info method=GET path="/admin/website/venue/1882/" host=www.speedyvenues.com request_id=0b774fd4-fe3a-4929-a5b4-94f855771400 fwd="116.203.74.26" dyno=web.1 connect=2ms service=2410ms status=200 bytes=199011
2015-10-10T08:06:38.870957+00:00 app[web.1]: {address space usage: 529453056 bytes/504MB} {rss usage: 68853760 bytes/65MB} [pid: 12|app: 0|req: 289/587] 10.171.114.17 () {56 vars in 1167 bytes} [Sat Oct 10 08:06:36 2015] GET /admin/website/venue/1882/ => generated 198675 bytes in 2406 msecs (HTTP/1.1 200) 7 headers in 336 bytes (2 switches on core 0)
2015-10-10T08:06:39.521145+00:00 app[web.1]: {address space usage: 529453056 bytes/504MB} {rss usage: 68853760 bytes/65MB} [pid: 12|app: 0|req: 290/588] 10.95.214.197 () {52 vars in 1020 bytes} [Sat Oct 10 08:06:39 2015] GET /admin/jsi18n/ => generated 2372 bytes in 97 msecs (HTTP/1.1 200) 3 headers in 93 bytes (1 switches on core 0)
2015-10-10T08:06:39.522541+00:00 heroku[router]: at=info method=GET path="/admin/jsi18n/" host=www.speedyvenues.com request_id=f962c405-1257-487d-a1ec-3b4da94157d0 fwd="116.203.74.26" dyno=web.1 connect=1ms service=99ms status=200 bytes=2465
2015-10-10T08:08:00.953726+00:00 app[web.1]: after calling django.save in admin.save, seconds passed= 127

I have tried to profile this module, I found that ftp upload takes most of the time. Mostly because Socket module is called many times. When I profiled it, it took around 8 secs to upload a file of 200-300 kB.However now the upload of file 800 kb takes much more time . Heroku says H12 is timeout error of more than 30secs.

Questions –

  • We get H12 error. But when I refresh ( as seen in the logs ) I get the output of print "after calling django.save ..." I believe the heroku error doesnt stop the uwsgi process and it continues in background. Am I correct in this assumption?
  • How can I upload to the ftp faster? Shall I use the ftp manually( using custom code) instead of using the django-storage solution? I can share the profiler results if anybody is interested.


Source: python

Leave a Reply