Spamsnake Ubuntu 12.04 - 504 Timeout

[JhonKa]

Hello,

After some issues, I finally got SpamSnake setup completely. I was testing the spam filter before I put it in production and noticed that after I either learn/preview message/delete a message from baruwa, the web server will stop responding and I get a 504 Timed out. The issue will resolve itself If I reboot the server, however it comes right back when I preview a message in the quarantine.

In the nginx error.log I am seeing this:

2013/01/03 09:38:49 [error] 2525#0: *167 upstream timed out (110: Connection timed out) while reading response header from upstream, client: (hidden), server: (hidden), request: "GET / HTTP/1.1", upstream: "uwsgi://unix:///var/run/uwsgi/app/baruwa/socket:", host: "(hidden)"

Do you guys have any ideas?

[Rocky]

Try running baruwa-admin migrate djcelery, reboot and see what happens

[JhonKa]

Thank you Rocky for the response! Unfortunately that didn't help at all. When I click Preview message it still just times out.

FWIW this is what happened when I ran the command:


Running migrations for djcelery:
- Nothing to migrate.
- Loading initial data for djcelery.
No fixtures found.

[Rocky]

Post your baruwa and uwsgi logs

[JhonKa]

Sorry about the long wait, I was out of town for the weekend.

My celeryd.log is here:


---- **** -----
--- * *** * -- [Configuration]
-- * - **** --- . broker: amqp://password@localhost:5672/baruwa
- ** ---------- . loader: djcelery.loaders.DjangoLoader
- ** ---------- . logfile: /var/log/baruwa/celeryd.log@INFO
- ** ---------- . concurrency: 2
- ** ---------- . events: ON
- *** --- * --- . beat: ON
-- ******* ----
--- ***** ----- [Queues]
-------------- . default: exchange:default (direct) binding:default
. gw3: exchange:default (direct) binding:gw3

[Tasks]
. delete-domain-signature-files
. delete-user-signature-files
. generate-domain-signature-files
. generate-user-signature-files
. preview-message
. process-quarantine
. process-quarantined-msg
. release-message
. test-smtp-server
[2013-01-07 10:37:19,259: INFO/PoolWorker-2] child process calling self.run()
[2013-01-07 10:37:19,267: INFO/PoolWorker-3] child process calling self.run()
[2013-01-07 10:37:19,277: INFO/Beat] child process calling self.run()
[2013-01-07 10:37:19,276: WARNING/MainProcess] celery@gw3 has started.
[2013-01-07 10:37:19,278: INFO/Beat] Celerybeat: Starting...
[2013-01-07 10:38:27,782: INFO/MainProcess] Got task from broker: preview-message[9261023c-4292-423c-a4cf-98e6469859ce]
[2013-01-07 10:38:27,840: INFO/PoolWorker-3] preview-message[9261023c-4292-423c-a4cf-98e6469859ce]: Preview of message: 27CD8C0DF7.AB05F requested by user:
[2013-01-07 10:38:27,854: INFO/MainProcess] Task preview-message[9261023c-4292-423c-a4cf-98e6469859ce] succeeded in 0.0686628818512s: {'headers': {'date': u'Mon, 07 Jan 2013...

As you can see it "successfully" previews the message.

uswgi logs:

[uWSGI] getting INI configuration from /usr/share/uwsgi/conf/default.ini
[uWSGI] getting INI configuration from /etc/uwsgi/apps-enabled/baruwa.ini
Mon Jan 7 10:07:56 2013 - option "module" found in plugin python27_plugin.so
Mon Jan 7 10:07:56 2013 - *** Starting uWSGI 1.0.3-debian (64bit) on [Mon Jan 7 10:07:56 2013] ***
Mon Jan 7 10:07:56 2013 - compiled with version: 4.6.3 on 17 July 2012 02:26:54
Mon Jan 7 10:07:56 2013 - current working directory: /
Mon Jan 7 10:07:56 2013 - writing pidfile to /run/uwsgi/app/baruwa/pid
Mon Jan 7 10:07:56 2013 - detected binary path: /usr/bin/uwsgi-core
Mon Jan 7 10:07:56 2013 - *** WARNING: you are running uWSGI as root !!! (use the --uid flag) ***
Mon Jan 7 10:07:56 2013 - your memory page size is 4096 bytes
Mon Jan 7 10:07:56 2013 - uwsgi socket 0 bound to UNIX address /run/uwsgi/app/baruwa/socket fd 5
Mon Jan 7 10:07:56 2013 - Python version: 2.7.3 (default, Aug 1 2012, 05:25:23) [GCC 4.6.3]
Mon Jan 7 10:07:57 2013 - Python main interpreter initialized at 0x2169870

And when I hit "preview message" in Baruwa this pops up in the uwsgi log.

/usr/lib/python2.7/dist-packages/djcelery/managers.py:173: TxIsolationWarning: Polling results with transaction isolation level repeatable-read within the same transaction may give outdated results. Be sure to commit the transaction for each poll iteration.
"Polling results with transaction isolation level "

[JhonKa]

I ripped out nginx & uwsgi and installed apache2. I was able to get into the web interface but I am still running into the same issues. I guess that means we can rule out the web server portion as the culprit.

EDIT: It looks like it doesn't 504 (possibly due to longer timeout times?) . I can also get back to the main page! When I tried it on nginx, baruwa would just lock up and i would have to restart the service.

[JhonKa]

Rocky,

I've discovered that rabbitmq closes the AMQP connection when i click on "preview message"

rabbitmq log:

=INFO REPORT==== 9-Jan-2013::13:50:38 ===
accepting AMQP connection <0.247.0> (127.0.0.1:55015 -> 127.0.0.1:5672)

then it shows this next message when i click "preview message"

=INFO REPORT==== 9-Jan-2013::13:50:38 ===
closing AMQP connection <0.247.0> (127.0.0.1:55015 -> 127.0.0.1:5672)

[Rocky]

Try reinstalling rabbitmq:

apt-get install rabbitmq-server

Restart and let me know what happens.

[JhonKa]

I found out that rabbitmq closes and opens a new connection for everything. So nothing is wrong with that. I did try to uninstall rabbitmq-server yesterday along with purging all the config files. Still no luck...

Are there any other logs i can post?

[jrossi90]

*bump
I am having the same issue. After I completed the install, everything worked great (including the preview and quarantine functions). After a reboot, I get the same issue described above. I can provide a little more insight - in the /var/log/uwsgi/app/baruwa.log I see the following right before it crashes:

Error opening file for reading: Permission denied
[pid: 2983|app: 0|req: 1/1] 10.10.10.16 () {40 vars in 853 bytes} [Fri May 17 21:53:25 2013] GET /messages/ => generated 2555 bytes in 519 msecs (HTTP/1.1 200) 6 headers in 297 bytes (1 switches on core 0)
[pid: 2984|app: 0|req: 1/2] 10.10.10.16 () {40 vars in 715 bytes} [Fri May 17 21:53:26 2013] GET /jsi18n/ => generated 2158 bytes in 224 msecs (HTTP/1.1 200) 2 headers in 72 bytes (1 switches on core 0)
Error opening file for reading: Permission denied
[pid: 2984|app: 0|req: 2/3] 10.10.10.16 () {40 vars in 876 bytes} [Fri May 17 21:53:29 2013] GET /messages/view/9B8C2B40E7E.A3BB4/ => generated 4204 bytes in 319 msecs (HTTP/1.1 200) 6 headers in 297 bytes (1 switches on core 0)
[pid: 2984|app: 0|req: 3/4] 10.10.10.16 () {40 vars in 738 bytes} [Fri May 17 21:53:30 2013] GET /jsi18n/ => generated 2158 bytes in 4 msecs (HTTP/1.1 200) 2 headers in 72 bytes (1 switches on core 0)


Any help would be greatly appreciated.

P.S Great howto, Rocky!