mhn-celery-worker Snort Update Fails

[Mark Robinson]

Hi,

I've followed; https://github.com/threatstream/mhn/wiki/MHN-Troubleshooting-Guide. When solving the log file issues and restarting the worker process it eventually falls over when importing the rules.

mark@ubuntu:/var/log/mhn$ tail -f mhn-celery-worker.err

bad rule?

Thanks

-Mark

[2015-06-25 16:46:48,061: INFO/Worker-1] Fetching sources from 1 sources.

[2015-06-25 16:46:48,071: INFO/Worker-1] Downloading from "http://rules.emergingthreats.net/open/snort-2.9.0/emerging.rules.tar.gz".

[2015-06-25 16:46:48,075: INFO/Worker-1] Starting new HTTP connection (1): rules.emergingthreats.net

[2015-06-25 16:48:43,984: INFO/Worker-1] Bulk importing 17939 rules.

[2015-06-25 16:48:50,588: INFO/Worker-2] Bulk importing 17939 rules.

[2015-06-25 16:48:56,939: WARNING/Worker-1] Imported 500 rules so far...

[2015-06-25 16:48:58,585: WARNING/Worker-2] Imported 500 rules so far...

[2015-06-25 16:49:06,299: WARNING/Worker-1] Imported 1000 rules so far...

[2015-06-25 16:49:07,875: WARNING/Worker-2] Imported 1000 rules so far...

[2015-06-25 16:49:14,224: WARNING/Worker-1] Imported 1500 rules so far...

[2015-06-25 16:49:17,040: WARNING/Worker-2] Imported 1500 rules so far...

[2015-06-25 16:49:22,158: WARNING/Worker-1] Imported 2000 rules so far...

[2015-06-25 16:49:26,411: WARNING/Worker-2] Imported 2000 rules so far...

[2015-06-25 16:49:31,433: WARNING/Worker-1] Imported 2500 rules so far...

[2015-06-25 16:49:35,834: WARNING/Worker-2] Imported 2500 rules so far...

[2015-06-25 16:49:40,243: WARNING/Worker-1] Imported 3000 rules so far...

[2015-06-25 16:49:44,384: WARNING/Worker-2] Imported 3000 rules so far...

[2015-06-25 16:49:48,911: WARNING/Worker-1] Imported 3500 rules so far...

[2015-06-25 16:49:52,973: WARNING/Worker-2] Imported 3500 rules so far...

[2015-06-25 16:49:57,611: WARNING/Worker-1] Imported 4000 rules so far...

[2015-06-25 16:50:01,065: WARNING/Worker-2] Imported 4000 rules so far...

[2015-06-25 16:50:07,799: WARNING/Worker-1] Imported 4500 rules so far...

[2015-06-25 16:50:10,666: WARNING/Worker-2] Imported 4500 rules so far...

[2015-06-25 16:50:15,449: WARNING/Worker-1] Imported 5000 rules so far...

[2015-06-25 16:50:19,821: WARNING/Worker-2] Imported 5000 rules so far...

[2015-06-25 16:50:24,366: ERROR/MainProcess] Task mhn.tasks.rules.fetch_sources[0aacdd26-0c85-48d9-acb0-abaf67935e2d] raised unexpected: OperationalError('(sqlite3.OperationalError) unable to open database file',)

Traceback (most recent call last):

  File "/opt/mhn/env/local/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task

    R = retval = fun(*args, **kwargs)

  File "/opt/mhn/server/mhn/tasks/__init__.py", line 13, in __call__

    return TaskBase.__call__(self, *args, **kwargs)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/celery/app/trace.py", line 437, in __protected_call__

    return self.run(*args, **kwargs)

  File "/opt/mhn/server/mhn/tasks/rules.py", line 77, in fetch_sources

    Rule.bulk_import(rules)

  File "/opt/mhn/server/mhn/api/models.py", line 185, in bulk_import

    rule.insert_refs(ru['references'])

  File "/opt/mhn/server/mhn/api/models.py", line 132, in insert_refs

    db.session.commit()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 150, in do

    return getattr(self.registry(), name)(*args, **kwargs)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 790, in commit

    self.transaction.commit()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 392, in commit

    self._prepare_impl()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl

    self.session.flush()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2004, in flush

    self._flush(objects)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2122, in _flush

    transaction.rollback(_capture_exception=True)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__

    compat.reraise(exc_type, exc_value, exc_tb)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2086, in _flush

    flush_context.execute()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute

    rec.execute(self)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute

    uow

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 174, in save_obj

    mapper, table, insert)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 761, in _emit_insert_statements

    execute(statement, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute

    return meth(self, multiparams, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection

    return connection._execute_clauseelement(self, multiparams, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement

    compiled_sql, distilled_params

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context

    context)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception

    exc_info

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause

    reraise(type(exception), exception, tb=exc_tb)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context

    context)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute

    cursor.execute(statement, parameters)

OperationalError: (sqlite3.OperationalError) unable to open database file [SQL: u'INSERT INTO rules (message, classtype, sid, rev, date, rule_format, is_active, notes) VALUES (?, ?, ?, ?, ?, ?, ?, ?)'] [parameters: ('ET CNC Shadowserver Reported CnC Server Port 22 Group 1', 'trojan-activity', 2405000, 3887, '2015-06-25 15:50:24.279065', 'alert tcp $HOME_NET any -> 50.116.1.225 22 ({msg}; flags:S; {reference}; threshold: type limit, track by_src, seconds 360, count 1; {classtype}; flowbits:set,ET.Evil; flowbits:set,ET.BotccIP; {sid}; {rev};)', 1, None)]

[2015-06-25 16:50:27,264: ERROR/MainProcess] Task mhn.tasks.rules.fetch_sources[aebb8e86-0094-4823-8c35-eec99a6280b9] raised unexpected: OperationalError('(sqlite3.OperationalError) unable to open database file',)

Traceback (most recent call last):

  File "/opt/mhn/env/local/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task

    R = retval = fun(*args, **kwargs)

  File "/opt/mhn/server/mhn/tasks/__init__.py", line 13, in __call__

    return TaskBase.__call__(self, *args, **kwargs)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/celery/app/trace.py", line 437, in __protected_call__

    return self.run(*args, **kwargs)

  File "/opt/mhn/server/mhn/tasks/rules.py", line 77, in fetch_sources

    Rule.bulk_import(rules)

  File "/opt/mhn/server/mhn/api/models.py", line 185, in bulk_import

    rule.insert_refs(ru['references'])

  File "/opt/mhn/server/mhn/api/models.py", line 132, in insert_refs

    db.session.commit()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 150, in do

    return getattr(self.registry(), name)(*args, **kwargs)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 790, in commit

    self.transaction.commit()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 392, in commit

    self._prepare_impl()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl

    self.session.flush()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2004, in flush

    self._flush(objects)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2122, in _flush

    transaction.rollback(_capture_exception=True)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__

    compat.reraise(exc_type, exc_value, exc_tb)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2086, in _flush

    flush_context.execute()

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute

    rec.execute(self)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute

    uow

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 174, in save_obj

    mapper, table, insert)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 761, in _emit_insert_statements

    execute(statement, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute

    return meth(self, multiparams, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection

    return connection._execute_clauseelement(self, multiparams, params)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement

    compiled_sql, distilled_params

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context

    context)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception

    exc_info

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause

    reraise(type(exception), exception, tb=exc_tb)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context

    context)

  File "/opt/mhn/env/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute

    cursor.execute(statement, parameters)

OperationalError: (sqlite3.OperationalError) unable to open database file [SQL: u'INSERT INTO rules (message, classtype, sid, rev, date, rule_format, is_active, notes) VALUES (?, ?, ?, ?, ?, ?, ?, ?)'] [parameters: ('ET CNC Shadowserver Reported CnC Server Port 22 Group 1', 'trojan-activity', 2405000, 3887, '2015-06-25 15:50:27.184830', 'alert tcp $HOME_NET any -> 50.116.1.225 22 ({msg}; flags:S; {reference}; threshold: type limit, track by_src, seconds 360, count 1; {classtype}; flowbits:set,ET.Evil; flowbits:set,ET.BotccIP; {sid}; {rev};)', 1, None)]

[2015-06-25 16:50:27,286: INFO/Worker-2] Fetching sources from 1 sources.

[2015-06-25 16:50:27,292: INFO/Worker-2] Downloading from "http://rules.emergingthreats.net/open/snort-2.9.0/emerging.rules.tar.gz".

[2015-06-25 16:50:27,297: INFO/Worker-2] Starting new HTTP connection (1): rules.emergingthreats.net

[2015-06-25 16:50:27,310: INFO/Worker-1] Fetching sources from 1 sources.

[2015-06-25 16:50:27,310: INFO/MainProcess] Received task: mhn.tasks.rules.fetch_sources[54f821d8-0bc7-441a-96f2-1ae0a081a13e]

[2015-06-25 16:50:27,314: INFO/Worker-1] Downloading from "http://rules.emergingthreats.net/open/snort-2.9.0/emerging.rules.tar.gz".

[2015-06-25 16:50:27,320: INFO/Worker-1] Starting new HTTP connection (1): rules.emergingthreats.net

[2015-06-25 16:50:27,321: INFO/MainProcess] Received task: mhn.tasks.rules.fetch_sources[09212e5c-4c9b-432b-883d-dab31b15fa95]

and then just loops.

[Jason Trost]

Mark,

To me this looks like either: 1) there is another process that have the Sqlite DB file open (i.e. mhn is running while you run this) or 2) the process running this script does not have permission to open the sqlite database (i.e. not running the script as root).

Are either of these the case?

--Jason

--
You received this message because you are subscribed to the Google Groups "Modern Honey Network" group.
To unsubscribe from this group and stop receiving emails from it, send an email to modern-honey-net...@googlegroups.com.
To post to this group, send email to modern-hon...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/modern-honey-network/9e273fa0-48df-41a2-b98b-73bcf48abada%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Jason Trost | Director of ThreatStream Labs | www.threatstream.com
2317 Broadway, 3rd Floor| Redwood City, CA 94063
Phone:  386.235.0078 | Twitter:  @jason_trost

[Mark Robinson]

It was all defaulted from the script. Its strange that it gets half way through the import THEN fails? permissions sound OK there.

1) there is another process that have the Sqlite DB file open (i.e. mhn is running while you run this)

2) the process running this script does not have permission to open the sqlite database (i.e. not running the script as root).

mark@ubuntu:~$ ps -ef | grep mon
mongodb    815     1  0 Jun24 ?        00:19:30 /usr/bin/mongod --config /etc/mongod.conf

/etc/mongod.conf

dbpath=/var/lib/mongodb
logpath=/var/log/mongodb/mongod.log
bind_ip = 127.0.0.1

root directory

4 drwxr-xr-x  4 mongodb mongodb 4096 Jun 25 14:50 mongodb

mark@ubuntu:/var/lib/mongodb$ ls -als
total 639004
     4 drwxr-xr-x  4 mongodb mongodb      4096 Jun 25 14:50 .
     4 drwxr-xr-x 44 root    root         4096 Jun  9 23:00 ..
 65536 -rw-------  1 mongodb nogroup  67108864 Jun 25 00:12 hpfeeds.0
 16384 -rw-------  1 mongodb nogroup  16777216 Jun 25 00:12 hpfeeds.ns
     4 drwxr-xr-x  2 mongodb nogroup      4096 Jun 24 21:10 journal
 65536 -rw-------  1 mongodb nogroup  67108864 Jun 24 21:10 local.0
 16384 -rw-------  1 mongodb nogroup  16777216 Jun 24 21:10 local.ns
 65540 -rw-------  1 mongodb nogroup  67108864 Jun 26 16:36 mnemosyne.0
131072 -rw-------  1 mongodb nogroup 134217728 Jun 26 16:36 mnemosyne.1
262148 -rw-------  1 mongodb nogroup 268435456 Jun 26 16:36 mnemosyne.2
 16384 -rw-------  1 mongodb nogroup  16777216 Jun 26 16:36 mnemosyne.ns
     4 -rwxr-xr-x  1 mongodb nogroup         4 Jun 24 21:09 mongod.lock
     4 drwxr-xr-x  2 mongodb nogroup      4096 Jun 25 14:50 _tmp

[Mark Robinson]

Sorry this database.

 

mark@ubuntu:/opt/mhn/server$ sudo lsof |grep mhn.db

celery    5766        www-data    7u      REG              252,0   11139072    1578343 /opt/mhn/server/mhn.db

celery    5767        www-data    7u      REG              252,0   11139072    1578343 /opt/mhn/server/mhn.db

 mark@ubuntu:/opt/mhn/server$ ll -h

total 11M

drwxr-xr-x 3 root     root     4.0K Jun 26 16:54 ./

drwxr-xr-x 6 root     root     4.0K Jun  9 22:18 ../

-rwxr-xr-x 1 www-data www-data  506 Jun  9 21:57 apikeys_migration.sh*

-rw-r--r-- 1 root     root        5 Jun 26 16:54 celerybeat.pid

-rw-r--r-- 1 root     root      12K Jun 26 16:54 celerybeat-schedule

-rw-r--r-- 1 www-data www-data  129 Jun  9 23:00 collector.json

-rw-r--r-- 1 www-data www-data  148 Jun  9 21:57 collector.json.example

-rw-r--r-- 1 www-data www-data 2.7K Jun  9 21:57 collector.py

-rw-r--r-- 1 www-data www-data 4.2K Jun  9 21:57 collector_v2.py

-rw-r--r-- 1 www-data www-data 2.1K Jun 25 10:00 config.py

-rw-r--r-- 1 root     root     2.5K Jun 25 16:21 config.pyc

-rw-r--r-- 1 www-data www-data 2.1K Jun  9 21:57 config.py.template

-rw-r--r-- 1 www-data www-data 7.2K Jun  9 21:57 generateconfig.py

-rw-r--r-- 1 www-data www-data   83 Jun  9 21:57 initdatabase.py

-rw-r--r-- 1 www-data www-data 1.7K Jun  9 21:57 manage.py

-rw-r--r-- 1 www-data www-data  736 Jun  9 21:57 manual_password_reset.py

drwxr-xr-x 9 www-data www-data 4.0K Jun  9 22:44 mhn/

-rw-r--r-- 1 www-data www-data  11M Jun 26 14:12 mhn.db

[Jason Trost]

Hmmm, any chance you ran out of disk space? If not, what version of Ubuntu is this? 

--
You received this message because you are subscribed to the Google Groups "Modern Honey Network" group.
To unsubscribe from this group and stop receiving emails from it, send an email to modern-honey-net...@googlegroups.com.
To post to this group, send email to modern-hon...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/modern-honey-network/9b77832d-b62e-4f98-b884-482420f92af5%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Mark Robinson]

Welcome to Ubuntu 14.04.2 LTS (GNU/Linux 3.16.0-41-generic x86_64)

* Documentation: https://help.ubuntu.com/

System information as of Fri Jun 26 17:22:38 BST 2015

System load: 1.89 Processes: 111
Usage of /: 17.9% of 37.04GB Users logged in: 1
Memory usage: 30% IP address for eth0: 10.0.0.7
Swap usage: 0%

Graph this data and manage this system at:
https://landscape.canonical.com/

Last login: Fri Jun 26 17:22:39 2015 from 10.242.2.6
mark@ubuntu:~$
mark@ubuntu:~$
mark@ubuntu:~$
mark@ubuntu:~$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/mapper/ubuntu--vg-root 38G 6.7G 29G 19% /
none 4.0K 0 4.0K 0% /sys/fs/cgroup
udev 990M 4.0K 990M 1% /dev
tmpfs 201M 692K 200M 1% /run
none 5.0M 0 5.0M 0% /run/lock
none 1001M 0 1001M 0% /run/shm
none 100M 0 100M 0% /run/user
/dev/sda1 236M 68M 156M 31% /boot
mark@ubuntu:~$

[Jim Clausing]

I'm running into the same issue on a brand new install also 14.04.2 LTS.  Any ideas?

---Jim

[Jim Clausing]

In fact, I chmod 666 mhn.db and still get the same error.  Doing a supervisorctl restart I'm now also getting the following 

[2015-07-10 14:37:43,773: WARNING/Worker-3] Traceback (most recent call last):

[2015-07-10 14:37:43,773: WARNING/Worker-3] File "/usr/lib/python2.7/logging/handlers.py", line 77, in emit

[2015-07-10 14:37:43,773: WARNING/Worker-3] self.doRollover()

[2015-07-10 14:37:43,773: WARNING/Worker-3] File "/usr/lib/python2.7/logging/handlers.py", line 142, in doRollover

[2015-07-10 14:37:43,773: WARNING/Worker-3] os.rename(self.baseFilename, dfn)

[2015-07-10 14:37:43,773: WARNING/Worker-3] OSError: [Errno 13] Permission denied

[2015-07-10 14:37:43,774: INFO/MainProcess] Received task: mhn.tasks.rules.fetch_sources[526bf04c-8e04-4dcc-8eef-f05aafe26d16]

[2015-07-10 14:37:43,776: INFO/MainProcess] Received task: mhn.tasks.rules.fetch_sources[76d17104-c2ef-4292-a4df-6b590c4a1842]

[2015-07-10 14:37:43,773: WARNING/Worker-3] Logged from file rules.py, line 31

[2015-07-10 14:37:43,772: INFO/Worker-3] Fetching sources from 1 sources.

[2015-07-10 14:37:43,778: WARNING/Worker-3] Traceback (most recent call last):

[2015-07-10 14:37:43,778: WARNING/Worker-3] File "/usr/lib/python2.7/logging/handlers.py", line 77, in emit

[2015-07-10 14:37:43,778: WARNING/Worker-3] self.doRollover()

[2015-07-10 14:37:43,778: WARNING/Worker-3] File "/usr/lib/python2.7/logging/handlers.py", line 142, in doRollover

[2015-07-10 14:37:43,779: WARNING/Worker-3] os.rename(self.baseFilename, dfn)

[2015-07-10 14:37:43,779: WARNING/Worker-3] OSError: [Errno 13] Permission denied

[2015-07-10 14:37:43,779: WARNING/Worker-3] Logged from file rules.py, line 35

[markpa...@gmail.com]

i have same issue ok guys try to slove the problem it's important otherwise just 20000 rules that import at fist time is not enough any idea to solve this problem?