Making OSSEC logging into mysql and not in .log anymore

[secatoor]

Hi all,

Like well explained in the OSSEC documentation, I "upgraded" my OSSEC
server to log into mysql database. I compiled OSSEC with setdb and
updated the previous installation.
I got mysql and OSSEC server working on the same machine.

I made the ossec database with the mysql.schema file and created the
"ossec" user account to allow connecting to mysql.

OSSEC starts up fine, and in the /var/ossec/logs/ossec.log file I can
see this line wich means to it should be able to connect correctly to
database:

2012/05/09 11:35:32 ossec-dbd: Connected to database 'ossec' at
'127.0.0.1'.


But... it seems working fine during a few minutes and then...
nothing !

When I connec to mysql to show the content of the "data" table (select
* from data) I get this:

+----+-----------+--------
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
+
| id | server_id | user |
full_log
|
+----+-----------+--------
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
+
| 1 | 1 | (null) | ossec: Ossec
started.
|
| 2 | 1 | root | May 7 16:57:29 vm3 sshd[2329]:
pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0
tty=ssh ruser= rhost=g-test.local user=root |
| 3 | 1 | root | May 7 16:57:30 vm3 sshd[2329]: Failed
password for root from 192.168.1.20 port 48068
ssh2
|
| 4 | 1 | root | May 7 16:57:43 vm3 sshd[2329]: Failed
password for root from 192.168.1.20 port 48068
ssh2
|
| 5 | 1 | root | May 7 16:57:44 vm3 sshd[2329]: Accepted
password for root from 192.168.1.20 port 48068
ssh2
|
| 6 | 1 | (null) | May 7 16:57:44 vm3 sshd[2329]:
pam_unix(sshd:session): session opened for user root by
(uid=0)
|
| 7 | 1 | (null) | May 7 16:57:48 vm3 sshd[2329]:
pam_unix(sshd:session): session closed for user
root
|
| 8 | 1 | (null) | May 7 17:25:32 vm3 sshd[2878]:
pam_unix(sshd:session): session opened for user root by
(uid=0)
|
| 9 | 1 | (null) | May 7 17:25:36 vm3 sshd[2878]:
pam_unix(sshd:session): session closed for user
root
|
| 10 | 1 | (null) | May 9 09:53:49 vm3 gnome-screensaver-
dialog: pam_unix(gnome-screensaver:auth): authentication failure;
logname= uid=1000 euid=1000 tty=:0.0 ruser= rhost= user=user |
| 11 | 1 | (null) | May 9 09:56:27 vm3 sshd[1993]: Invalid
user test from
192.168.1.20
|
| 12 | 1 | (null) | May 9 09:56:27 vm3 sshd[1993]: Failed
none for invalid user test from 192.168.1.20 port 39825
ssh2 |
+----+-----------+--------
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------
+
12 rows in set (0.00 sec)


Which shows that I succeeded to connect via ssh with my "root" account
and that I tried with a false account.

But the next hour I tried to log again with a false account (to check
if OSSEC is working fine) and nothing had been logged into mysql...

And when I open the /var/ossec/logs/archives/2012/May/ossec-
archive-09.log file, I can observe things like :

2012 May 09 11:36:10 vm3->/var/log/auth.log May 9 11:36:10 vm3
sshd[2038]: Invalid user foker from 192.168.1.20
2012 May 09 11:36:10 vm3->/var/log/auth.log May 9 11:36:10 vm3
sshd[2038]: Failed none for invalid user foker from 192.168.1.20 port
39834 ssh2
2012 May 09 11:36:14 vm3->/var/log/auth.log May 9 11:36:13 vm3
sshd[2038]: pam_unix(sshd:auth): check pass; user unknown
2012 May 09 11:36:14 vm3->/var/log/auth.log May 9 11:36:13 vm3
sshd[2038]: pam_unix(sshd:auth): authentication failure; logname=
uid=0 euid=0 tty=ssh ruser= rhost=g-test.local
2012 May 09 11:36:16 vm3->/var/log/auth.log May 9 11:36:15 vm3
sshd[2038]: Failed password for invalid user foker from 192.168.1.20
port 39834 ssh2
2012 May 09 11:36:18 vm3->/var/log/auth.log May 9 11:36:16 vm3
sshd[2038]: pam_unix(sshd:auth): check pass; user unknown
2012 May 09 11:36:20 vm3->/var/log/auth.log May 9 11:36:18 vm3
sshd[2038]: Failed password for invalid user foker from 192.168.1.20
port 39834 ssh2
2012 May 09 11:36:20 vm3->/var/log/auth.log May 9 11:36:19 vm3
sshd[2038]: pam_unix(sshd:auth): check pass; user unknown
2012 May 09 11:36:22 vm3->/var/log/auth.log May 9 11:36:21 vm3
sshd[2038]: Failed password for invalid user foker from 192.168.1.20
port 39834 ssh2
2012 May 09 11:36:22 vm3->/var/log/auth.log May 9 11:36:21 vm3
sshd[2038]: PAM 2 more authentication failures; logname= uid=0 euid=0
tty=ssh ruser= rhost=g-test.local

That makes understand that OSSEC is logging but not in the database...
I checked the /var/ossec/logs/ossec.log file again and there was no
problem with dbd.

Is there something specific I have to tell OSSEC to make it stop
logging into log files and log into mysql database ?

I tried starting it again and again but it still does not work fine (I
even tried from scratch, with no previous installation)...

If someone has any idea, you're welcome ;)
Thanks

[dan (ddp)]

Is ossec-dbd still running? Any errors in your mysql log file?

Warm up your text editor, you'll have to write some code.

[secatoor]

Hi dan,

With ps aux | grep dbd I get this:

ossecm    2006  0.0  0.4   5372  2124 ?        S    11:35   0:00 /var/ossec/bin/ossec-dbd

So yes, dbd seems to be still running and there is no error in ossec.log file.
Both /var/log/mysql.log and /var/log/mysql.err are empty, seems to be no more information (may be I should change mysql logging level).

Texte editor is ready to get creative :)

Thanks

[dan (ddp)]

On Wed, May 9, 2012 at 9:03 AM, secatoor <seca...@gmail.com> wrote:
> Hi dan,
>
> With ps aux | grep dbd I get this:
>
> ossecm    2006  0.0  0.4   5372  2124 ?        S    11:35   0:00
> /var/ossec/bin/ossec-dbd
>
> So yes, dbd seems to be still running and there is no error in ossec.log
> file.
> Both /var/log/mysql.log and /var/log/mysql.err are empty, seems to be no
> more information (may be I should change mysql logging level).
>

Perhaps running ossec-dbd in debug mode might help. I don't use
ossec-dbd so I'm not really much help.

[secatoor]

I activated mysql logging (it wasn't enabled).

Now in /var/log/mysql/mysql.log I can see:
                  121 Connect   ossecuser@localhost on ossec
120509 16:30:13   121 Query     INSERT INTO data(id, server_id, user, full_log) VALUES ('7', '1', 'root', 'May  9 16:30:09 vm3 sshd[3407]: Accepted password for root from 192.168.1.20 port 40122 s$
                  121 Quit

But when I connect to the database as root and I use "select * from data" I still do not see the lines that mysql should have inserted (like wroten above).

That's realy queer ! Seems that there something wrong with mysql...

On Wednesday, May 9, 2012 1:16:47 PM UTC+2, secatoor wrote:

[Scott VR]

On May 9, 2012, at 6:16 AM, secatoor <seca...@gmail.com> wrote:

> Is there something specific I have to tell OSSEC to make it stop
> logging into log files and log into mysql database ?
>

Did you set database_output and appropriate credential, etc parameters in ossec.conf?

See http://www.ossec.net/doc/manual/output/database-output.html

It sounds like you completed "Enabling database support", but missed "Enabling database output in configuration" perhaps.

ScottVR

[Scott VR]

[secatoor]

Hi scott,

Yes I configured the database output also, like this:

 <database_output>
      <hostname>localhost</hostname>
      <port>3306</port>
      <username>ossecuser</username>
      <password>password</password>
      <database>ossec</database>
      <type>mysql</type>
  </database_output>

Like I said, you really can see that OSSEC sends SQL requests into mysql (viewable in mysql.log).

But they don't appear in the database... Is there a kind of time out or other parameter I should modify ?



On Thursday, May 10, 2012 1:54:04 AM UTC+2, Scott VR wrote:

On May 9, 2012, at 11:35 AM, Scott VR wrote:

[Scott VR]

Well, like dan I don't actually use it, but like you, I have configured it.

What dan said about writing code is of interest here, I think.. And might be the key to what you want. Perhaps Dan will elaborate on what he meant. Maybe the database feature is incomplete, hence his suggestion that you fire up a text editor?

Scott

On May 10, 2012, at 4:36 AM, secatoor <seca...@gmail.com> wrote:

Hi Scott,

Yes I did configure the "database output", otherwise we wouldn't see the actions in mysql.log, these are the parameters I used:

    <database_output>

        <hostname>localhost</hostname>

<username>ossecuser</username>

        <password>password</password>

        <database>ossec</database>

        <type>mysql</type>

    </database_output>

There must be something wrong with mysql, is ther something (timeout or maxConnection) that I should change ?

Le mercredi 9 mai 2012 18:35:32 UTC+2, Scott VR a écrit :

[dan (ddp)]

On Thu, May 10, 2012 at 8:35 AM, Scott VR <sco...@s0cialpath.net> wrote:
> Well, like dan I don't actually use it, but like you, I have configured it.
>
> What dan said about writing code is of interest here, I think.. And might be
> the key to what you want. Perhaps Dan will elaborate on what he meant. Maybe
> the database feature is incomplete, hence his suggestion that you fire up a
> text editor?
>
> Scott
>

It works for most people, and I think it's used heavily by some
users.While I don't think the db stuff is feature complete, that's not
what I meant.

There is currently no way to not log to text files, and to change that
you'd have to modify the source code. This isn't something I'd
consider a feature though.

[secatoor]

Well, stoping OSSEC loggingg to log files is not really the problem, I can handle that with a script...

What I really would like to have is all the logs into mysql because the volume of generated logs is too important to be crawled with a single script :(

I really can not understand why mysql shows me all the INSERT and UPDATE commands but does not execute them (not anymore, it worked only for 12 lines)...

Le jeudi 10 mai 2012 14:44:03 UTC+2, dan (ddpbsd) a écrit :

[Scott VR]

Ah, I see now. I confess I didn't pay too detailed attention to the actual SQL pastes, just your comments on them. 

I suggest the way to look at this then is "why are my inserts and updates not committing?" (i.e., look at MySQL and not OSSEC as the problem) and then I  personally will bow out, as I am decidedly not a dba. :)

Cheers.

[dan (ddp)]

On Thu, May 10, 2012 at 11:32 AM, secatoor <seca...@gmail.com> wrote:
> Well, stoping OSSEC loggingg to log files is not really the problem, I can
> handle that with a script...
>
> What I really would like to have is all the logs into mysql because the
> volume of generated logs is too important to be crawled with a single script
> :(
>
>
> I really can not understand why mysql shows me all the INSERT and UPDATE
> commands but does not execute them (not anymore, it worked only for 12
> lines)...
>

Did you ever try running ossec-dbd in debug mode?
Do the mysql logs show the insert or whether it was successful or not?
If not, you might want to increase the verbosity or something.

[secatoor]

Thanks scott ;)

Yep, I tried using dbd with -d for debug mode but I do not understand where the debbuging logs go to... I'm actually looking to make mysql more talkative about the insertions and updates, I'll keep you informed when succeeded.

On Thursday, May 10, 2012 8:09:26 PM UTC+2, dan (ddpbsd) wrote:

[dan (ddp)]

On Fri, May 11, 2012 at 3:19 AM, secatoor <seca...@gmail.com> wrote:
> Thanks scott ;)
>
> Yep, I tried using dbd with -d for debug mode but I do not understand where
> the debbuging logs go to... I'm actually looking to make mysql more
> talkative about the insertions and updates, I'll keep you informed when
> succeeded.
>

Debug logs go to /var/ossec/logs/ossec.log along with the regular logs.

[secatoor]

Hi,

I don't find any option to make mysl more talkative (there is no log level option). I thought it could be linked with the number of simultaneous sessions, but I still can connect to with the ossec user myself !

By the way dbd in debug mode don't gives me anything more than this:

2012/05/14 09:24:57 ossec-dbd: DEBUG: Starting ...

2012/05/14 09:24:57 adding rule: rules_config.xml

2012/05/14 09:24:57 adding rule: pam_rules.xml

2012/05/14 09:24:57 adding rule: sshd_rules.xml

2012/05/14 09:24:57 adding rule: telnetd_rules.xml

2012/05/14 09:24:57 adding rule: syslog_rules.xml

2012/05/14 09:24:57 adding rule: arpwatch_rules.xml

2012/05/14 09:24:57 adding rule: symantec-av_rules.xml

2012/05/14 09:24:57 adding rule: symantec-ws_rules.xml

2012/05/14 09:24:57 adding rule: pix_rules.xml

2012/05/14 09:24:57 adding rule: named_rules.xml

2012/05/14 09:24:57 adding rule: smbd_rules.xml

2012/05/14 09:24:57 adding rule: vsftpd_rules.xml

2012/05/14 09:24:57 adding rule: pure-ftpd_rules.xml

2012/05/14 09:24:57 adding rule: proftpd_rules.xml

2012/05/14 09:24:57 adding rule: ms_ftpd_rules.xml

2012/05/14 09:24:57 adding rule: ftpd_rules.xml

2012/05/14 09:24:57 adding rule: hordeimp_rules.xml

AND ALL THE OTHER RULES...

AND THEN :

2012/05/14 09:24:57 ossec-dbd: DEBUG: Connecting to '127.0.0.1', using 'XXXX', 'XXXXX', 'ossec', 0,'(null)'.

2012/05/14 09:24:57 ossec-dbd: Connected to database 'ossec' at '127.0.0.1'.

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering OS_Server_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: Reading rules file: 'rules_config.xml'

2012/05/14 09:24:57 ossec-dbd: DEBUG: read xml for rule '/rules/rules_config.xml'.

2012/05/14 09:24:57 ossec-dbd: DEBUG: XML Variables applied.

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: Reading rules file: 'pam_rules.xml'

2012/05/14 09:24:57 ossec-dbd: DEBUG: read xml for rule '/rules/pam_rules.xml'.

2012/05/14 09:24:57 ossec-dbd: DEBUG: XML Variables applied.

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

AND SO ON !

As you can see OSSEC succesfully connects to mysql. I think there must be something with mysql, but because I don't get it's log verbose higher it's not going to be easy.

Any idea ?

On Friday, May 11, 2012 2:09:18 PM UTC+2, dan (ddpbsd) wrote:

[dan (ddp)]

What are the last few logs you see from ossec-dbd? This all looks like
startup stuff, I'm hoping to see something about inserts.

This is a similar situation to the mysql log line you gave us earlier.
It feels like you didn't give us enough. Was there a message after the
log message you posted? Something that might have hinted at the
success or failure of the insert?

>
> As you can see OSSEC succesfully connects to mysql. I think there must be
> something with mysql, but because I don't get it's log verbose higher it's
> not going to be easy.
>
> Any idea ?
>

Check permissions on the database for the ossec user? Delete and
recreate the ossec database? Ask your DBA? Add more logging to
ossec-dbd?

[secatoor]

The last logs from ossec-dbd are those:

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()

2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB

2012/05/14 09:34:03 ossec-syscheckd: INFO: Starting syscheck scan.

2012/05/14 09:43:04 ossec-syscheckd: INFO: Ending syscheck scan.

As you can see there is nothing interresting, after dbd starts up syscheck starts and logs some data. I got no more information than just that useless one... Even if I start mysql with  --log-warning

 option.

Today while restarting OSSEC I did notice this:

/var/ossec/bin/ossec-control restart

Deleting PID file '/var/ossec/var/run/ossec-remoted-1720.pid' not used...

Deleting PID file '/var/ossec/var/run/ossec-dbd-1692.pid' not used...

Deleting PID file '/var/ossec/var/run/ossec-dbd-2034.pid' not used...

Deleting PID file '/var/ossec/var/run/ossec-dbd-2045.pid' not used...

Deleting PID file '/var/ossec/var/run/ossec-dbd-2053.pid' not used...

Deleting PID file '/var/ossec/var/run/ossec-dbd-2059.pid' not used...

Is an unused pid bad news ?

I already deleted and recreated the databse from scratch three times, I'll try it again but it don't helps...

It's strange because when watching the /var/log/mysql/mysql.log whith "tail -f" and connecting via SSH, I can see that ossec-dbd is logging....

  49 Connect ossecuser@localhost on ossec

                   49 Query INSERT INTO data(id, server_id, user, full_log) VALUES ('3', '1', 'root', 'May 14 16:01:26 vm3 sshd[3850]: Accepted password for root from 192.168.1.20 port 36647 ssh2')

  49 Query INSERT INTO alert(id,server_id,rule_id,timestamp,location_id,src_ip,src_port,dst_ip,dst_port,alertid) VALUES ('3', '1', '5715','1337004092', '2', '3232235796', '23824', '0', '23776', '1337004088.7515')

  49 Quit

As you can see there are INSERT commands but nothing says if it succeeded or not.

I also noticed something that seems important !

I just droped complete database and when database is just freshly recreated it starts to log without any problem, (if I use "select * from data" it shows every action that happend since ossec started).

I see exactly the same things hapenning in the mysql.log file than before (when it wasn't working).

I hope it will keep on working...

On Monday, May 14, 2012 3:26:19 PM UTC+2, dan (ddpbsd) wrote:

[dan (ddp)]

On Mon, May 14, 2012 at 11:22 AM, secatoor <seca...@gmail.com> wrote:
> The last logs from ossec-dbd are those:
>
>
> 2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Rules_ReadInsertDB()
> 2012/05/14 09:24:57 ossec-dbd: DEBUG: entering _Groups_ReadInsertDB
> 2012/05/14 09:34:03 ossec-syscheckd: INFO: Starting syscheck scan.
> 2012/05/14 09:43:04 ossec-syscheckd: INFO: Ending syscheck scan.
>
> As you can see there is nothing interresting, after dbd starts up syscheck
> starts and logs some data. I got no more information than just that useless
> one... Even if I start mysql with  --log-warning
>  option.
>
> Today while restarting OSSEC I did notice this:
>
> /var/ossec/bin/ossec-control restart
> Deleting PID file '/var/ossec/var/run/ossec-remoted-1720.pid' not used...
> Deleting PID file '/var/ossec/var/run/ossec-dbd-1692.pid' not used...
> Deleting PID file '/var/ossec/var/run/ossec-dbd-2034.pid' not used...
> Deleting PID file '/var/ossec/var/run/ossec-dbd-2045.pid' not used...
> Deleting PID file '/var/ossec/var/run/ossec-dbd-2053.pid' not used...
> Deleting PID file '/var/ossec/var/run/ossec-dbd-2059.pid' not used...
>
> Is an unused pid bad news ?
>

It's possible that ossec-dbd wasn't running, or didn't shut down
properly. The pid file should have been deleted.

[secatoor]

Well I know that even with "unused pid" ossec-dbd is working because I can see that it tries to writte to DB (it's logged in mysql.log).

Like I told you yesterday, after building database from scratch its working fine, I turned off the computer,  started it today and now it isn't working anymore...

Ossec-dbd actions are still  logged in mysql.log but nothing appears into the database itself and I got no more error infromation.

So I tried starting ossec and mysql one after the other in both ways, everything looks normal:

-If mysql starts before ossec, I can see this in ossec.log: 2012/05/15 09:57:23 ossec-dbd: Connected to database 'ossec' at '127.0.0.1'.

-If mysql starts after ossec, I can see this in ossec.log: 2012/05/15 10:41:26 ossec-dbd(5202): ERROR: Error connecting to database '127.0.0.1'(ossec): ERROR: Can't connect to MySQL server on '127.0.0.1' (111).

Now I'm sure that OSSEC really connects to database, I'm quitte sure there is something with mysql but why ? Are there temporary rights that may vanish, I tried to INSERT the ossec data by myself (by copying the commands shown in /var/lo/mysql/mysql.log) and mysql says that I'm duplicating the id (of the row)...

Well now we now ! When OSSEC is starting it don't looks for the highest id allready existing, is starts logging from id 1 and when it already exists well it fails (but I couldn't see it because I didn't got the mysql server response).

Strange...!

On Monday, May 14, 2012 5:33:15 PM UTC+2, dan (ddpbsd) wrote: