search

MHMDhub / enterprise-log-search-and-archive

Automatically exported from code.google.com/p/enterprise-log-search-and-archive
0 stars 0 forks source link

Logs loading but no results in Web UI #7

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
I now have logs loading and can see them in the syslog and syslog_data tables.  
But nothing I have tried shows any results in the Web UI so far.

I see there is data being parsed into some fields properly but just nothing 
coming back to the Web UI.

I have tried to query for stuff that I know is in the syslogs_index_1 table and 
I get nothing back.

What information is needed to help troubleshoot this?

Original issue reported on code.google.com by edavi...@gmail.com on 13 Feb 2012 at 10:58

GoogleCodeExporter commented 9 years ago 
Try this query:
class=none
in the web UI.

If that doesn't work, run this in the database:
SELECT AVG(LENGTH(msg)) FROM syslog_data.syslogs_index_1;
SELECT * FROM syslog_data.syslogs_index_1 LIMIT 1;

Also, verify that Sphinx is working.  Find the biggest index:
ls -lhrS /data/elsa/sphinx/*.spi
It should be perm_n or temp_n where n is a number.  Look at the MySQL query 
above and pick a word from a log to query for.  Query that index like this:
mysql -P3307 -e "SELECT * FROM perm_n WHERE MATCH('word_from_above')"

Original comment by mchol...@gmail.com on 14 Feb 2012 at 2:37

GoogleCodeExporter commented 9 years ago 
When I run the "class=none" query I get an error next to the "Result Options" 
button:

Errors: index 
perm_1,perm_10,perm_11,perm_12,perm_13,perm_2,perm_3,perm_4,perm_5,perm_6,perm_7
,perm_8,perm_9: fullscan requires extern docinfo

mysql> select count(*) from syslog_data.syslogs_index_1;
+----------+
| count(*) |
+----------+
|  7419915 |
+----------+
1 row in set (0.00 sec)

mysql> SELECT AVG(LENGTH(msg)) FROM syslog_data.syslogs_index_1;
+------------------+
| AVG(LENGTH(msg)) |
+------------------+
|         631.6688 |
+------------------+
1 row in set (56.53 sec)

mysql> SELECT * FROM syslog_data.syslogs_index_1 LIMIT 1;
+----+------------+------------+------------+----------+------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-----------------------+------+------+------+------+------+------+------+------+
------+------+------+------+
| id | timestamp  | host_id    | program_id | class_id | msg                    

                       | i0   | i1   | i2   | i3   | i4   | i5   | s0   | s1   
| s2   | s3   | s4   | s5   |
+----+------------+------------+------------+----------+------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-----------------------+------+------+------+------+------+------+------+------+
------+------+------+------+
|  1 | 1328732255 | 2130706433 | 1584708348 |        1 | seq: 0000000000, 
runid: 1328732255, stamp: 2012-02-08T14:17:35 
PADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADD
PADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPA | NULL | NULL | 
NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL |
+----+------------+------------+------------+----------+------------------------
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
-----------------------+------+------+------+------+------+------+------+------+
------+------+------+------+
1 row in set (0.02 sec)

For some reason I do not have a sphinx directory there:

# ls -lhrS /data/elsa/
total 16K
drwxr-xr-x 3 root   root 4.0K Feb  8 14:16 tmp
drwxr-xr-x 2 apache root 4.0K Feb 13 09:26 log

But I do have /data/sphinx with .spi files.

# mysql -P3307 -e "SELECT * FROM perm_n WHERE MATCH('traffic')"
ERROR 1046 (3D000) at line 1: No database selected

Original comment by edavi...@gmail.com on 14 Feb 2012 at 4:35

GoogleCodeExporter commented 9 years ago 
Ok, so logs are definitely making it into ELSA just fine, so it's probably a 
Sphinx issue.

I was mistaken, it is indeed /data/sphinx, not /data/elsa/sphinx.

One other mistake, the MySQL command needs the host in addition to the port to 
connect to Sphinx like this:
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_n WHERE MATCH('traffic')"

"perm_n" should be one of the *.spi file names that had more than just a few 
bytes, and "traffic" should be a word that will match.  For instance, the 
earliest index (temp_1), probably should contain the word "seq" as shown above, 
so the query should be:
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM temp_1 WHERE MATCH('seq')"

Original comment by mchol...@gmail.com on 14 Feb 2012 at 6:46

GoogleCodeExporter commented 9 years ago 
Ah, ok.  So here is perm_1 matching 'traffic':

# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE MATCH('traffic')"
+-------+--------+------------+-------+--------+----------+------------+--------
----+----------+------------+---------+------------+---------+---------+--------
-+---------+---------+---------+---------+---------+---------+
| id    | weight | timestamp  | day   | hour   | minute   | host_id    | 
program_id | class_id | attr_i0    | attr_i1 | attr_i2    | attr_i3 | attr_i4 | 
attr_i5 | attr_s0 | attr_s1 | attr_s2 | attr_s3 | attr_s4 | attr_s5 |
+-------+--------+------------+-------+--------+----------+------------+--------
----+----------+------------+---------+------------+---------+---------+--------
-+---------+---------+---------+---------+---------+---------+
| 52266 |   1486 | 1329170279 | 15384 | 369214 | 22152838 | 2886740029 | 
1574083243 |        1 |          0 |       0 |          0 |       0 |       0 | 
      0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 52267 |   1486 | 1329170279 | 15384 | 369214 | 22152838 | 2886740029 | 
1574083243 |       22 | 2887391998 |   52426 | 2538464064 |   27459 |       0 | 
    183 |       0 |       0 |       0 |       0 |       0 |       0 |
...

Original comment by edavi...@gmail.com on 14 Feb 2012 at 11:10

GoogleCodeExporter commented 9 years ago 
Ok, good, this shows that rows are in fact making it into Sphinx and are being 
parsed correctly (note the row with class_id 22).  Verify that the row exists 
as indicated like this:
mysql -e "SELECT * FROM syslog_data.syslogs_index_1 WHERE id=52267"
If the row looks good, then it is only a web problem.  In that case, what 
errors show up in /data/elsa/log/web.log?

Original comment by mchol...@gmail.com on 15 Feb 2012 at 2:34

GoogleCodeExporter commented 9 years ago 
Yes, agreed. The row is in the query results:

| 52267 | 1329170279 | 2886740029 | 1574083243 |       22 | date=2012-02-13 
time=15:58:09 devname=CUSTID01-SITEID-FW device_id=FG100A9999999 log_id=2 
subtype=allowed type=traffic pri=notice vd=vd dir_disp=org tran_disp=snat 
src=1.2.3.4 srcname=1.2.3.4 src_port=52426 dst=2.3.4.5 dstname=2.3.4.5 
dst_port=27459 tran_ip=3.4.5.6 tran_port=55374 service=27459/udp proto=17 
app_type=N/A duration=183 rule=3 policyid=3 identidx=0 sent=116 rcvd=0 
shaper_drop_sent=0 shaper_drop_rcvd=0 perip_drop=0 sent_pkt=2 rcvd_pkt=0 
src_int=dmz1 dst_int=wan1 SN=38809844 app=N/A app_cat=N/A carrier_ep=N/A 
vpn=N/A status=accept user=N/A group=N/A shaper_sent_name=N/A 
shaper_rcvd_name=N/A perip_name=N/A | 2887391998 | 52426 | 2538464064 | 27459 | 
   0 |  183 | NULL | NULL | NULL | NULL | NULL | NULL |

Checking web.log.

Original comment by edavi...@gmail.com on 15 Feb 2012 at 3:03

GoogleCodeExporter commented 9 years ago 
Attaching excerpt from web log.  Still just get the error stated before.

Also, here is the result of the query for the index tables available:

+---------+---------------------+------------+---------------------+------------
+-----------+----------+
| name    | start               | start_int  | end                 | end_int    
| type      | records  |
+---------+---------------------+------------+---------------------+------------
+-----------+----------+
| perm_17 | 2012-02-08 14:17:35 | 1328732255 | 2012-02-14 15:02:31 | 1329253351 
| permanent | 10000578 |
| perm_1  | 2012-02-14 15:02:31 | 1329253351 | 2012-02-14 16:27:39 | 1329258459 
| permanent |   785643 |
| perm_2  | 2012-02-14 16:27:39 | 1329258459 | 2012-02-14 17:49:50 | 1329263390 
| permanent |   638751 |
| perm_3  | 2012-02-14 17:49:50 | 1329263390 | 2012-02-14 19:11:57 | 1329268317 
| permanent |   511761 |
| perm_4  | 2012-02-14 19:11:57 | 1329268317 | 2012-02-14 20:34:06 | 1329273246 
| permanent |   421288 |
| perm_5  | 2012-02-14 20:34:06 | 1329273246 | 2012-02-14 21:56:12 | 1329278172 
| permanent |   476145 |
| perm_6  | 2012-02-14 21:56:12 | 1329278172 | 2012-02-14 23:18:22 | 1329283102 
| permanent |   487728 |
| perm_7  | 2012-02-14 23:18:22 | 1329283102 | 2012-02-15 00:40:31 | 1329288031 
| permanent |   470357 |
| perm_8  | 2012-02-15 00:40:31 | 1329288031 | 2012-02-15 02:02:38 | 1329292958 
| permanent |   494328 |
| perm_9  | 2012-02-15 02:02:39 | 1329292959 | 2012-02-15 03:24:44 | 1329297884 
| permanent |   482317 |
| perm_10 | 2012-02-15 03:24:45 | 1329297885 | 2012-02-15 04:46:53 | 1329302813 
| permanent |   462564 |
| perm_11 | 2012-02-15 04:46:54 | 1329302814 | 2012-02-15 06:09:02 | 1329307742 
| permanent |   477186 |
| perm_12 | 2012-02-15 06:09:02 | 1329307742 | 2012-02-15 07:31:11 | 1329312671 
| permanent |   522163 |
| perm_13 | 2012-02-15 07:31:11 | 1329312671 | 2012-02-15 08:53:21 | 1329317601 
| permanent |   647904 |
| temp_82 | 2012-02-15 08:53:21 | 1329317601 | 2012-02-15 08:54:21 | 1329317661 
| temporary |     9963 |
| temp_84 | 2012-02-15 08:54:21 | 1329317661 | 2012-02-15 08:55:21 | 1329317721 
| temporary |     9336 |
| temp_1  | 2012-02-15 08:55:21 | 1329317721 | 2012-02-15 08:56:22 | 1329317782 
| temporary |    10811 |
| temp_2  | 2012-02-15 08:56:22 | 1329317782 | 2012-02-15 08:57:22 | 1329317842 
| temporary |     9499 |
| temp_3  | 2012-02-15 08:57:22 | 1329317842 | 2012-02-15 08:58:22 | 1329317902 
| temporary |     9557 |
| temp_4  | 2012-02-15 08:58:23 | 1329317903 | 2012-02-15 08:59:22 | 1329317962 
| temporary |     9465 |
| temp_5  | 2012-02-15 08:59:23 | 1329317963 | 2012-02-15 09:00:23 | 1329318023 
| temporary |    10014 |
| temp_6  | 2012-02-15 09:00:23 | 1329318023 | 2012-02-15 09:01:22 | 1329318082 
| temporary |    10264 |
| temp_7  | 2012-02-15 09:01:23 | 1329318083 | 2012-02-15 09:02:23 | 1329318143 
| temporary |     9108 |
| temp_8  | 2012-02-15 09:02:23 | 1329318143 | 2012-02-15 09:03:23 | 1329318203 
| temporary |     9387 |
| temp_9  | 2012-02-15 09:03:23 | 1329318203 | 2012-02-15 09:04:22 | 1329318262 
| temporary |    15035 |
| temp_10 | 2012-02-15 09:04:23 | 1329318263 | 2012-02-15 09:05:23 | 1329318323 
| temporary |     8749 |
| temp_11 | 2012-02-15 09:05:23 | 1329318323 | 2012-02-15 09:06:23 | 1329318383 
| temporary |     9358 |
+---------+---------------------+------------+---------------------+------------
+-----------+----------+

Original comment by edavi...@gmail.com on 15 Feb 2012 at 3:10

GoogleCodeExporter commented 9 years ago 
attach file

Original comment by edavi...@gmail.com on 15 Feb 2012 at 3:11

Attachments:

GoogleCodeExporter commented 9 years ago 
Try searching for just "traffic" in the web UI.  All of the backend stuff looks 
good, it's just not searching for any keywords.

Original comment by mchol...@gmail.com on 15 Feb 2012 at 3:18

GoogleCodeExporter commented 9 years ago 
query for Traffic returns an empty query.

Field Summary
Records: 0 / 0 1068 ms < prev next >

Timestamp

Fields
No records found.
Records: 0 / 0 1068 ms < prev next >

Original comment by edavi...@gmail.com on 15 Feb 2012 at 11:53

GoogleCodeExporter commented 9 years ago 
Ok, what does the web.log look like now?

Original comment by mchol...@gmail.com on 16 Feb 2012 at 1:23

GoogleCodeExporter commented 9 years ago 
attached

Original comment by edavi...@gmail.com on 16 Feb 2012 at 4:16

Attachments:

GoogleCodeExporter commented 9 years ago 
Very odd, Sphinx does just fine and finds 1344657 hits for your query, but then 
it can't find the corresponding MySQL tables that have the right log ID's 
stored in them to match the found results.  Can you add these lines at 
elsa/web/lib/API.pm line 2662:

$self->add_warning('No MySQL tables found for search hits.');
$self->log->error('No tables found for result. tables: ' . 
Dumper($args->{node_info}->{nodes}->{$node}->{tables}));

Then show me the output from the log there.  I'm trying to find out what tables 
it does know about, as there's no good reason for it to not know about the 
right tables.

Original comment by mchol...@gmail.com on 16 Feb 2012 at 5:14

GoogleCodeExporter commented 9 years ago 
Added.  No change in output or log file.

This is how my source code looks just before and with those changes.  Is this 
the right place you wanted the code placed?

                                                        foreach my $row (@$rows){
                                                                $ret->{$node}->{results} ||= {};
                                                                $row->{node} = $node;
                                                                $row->{node_id} = unpack('N*', inet_aton($node));
                                                                $ret->{$node}->{results}->{ $row->{id} } = $row;
                                                        }
                                                        $cv->end;
                                                },
                                                @table_query_values);
                                        $cv->end; #end sphinx query
                                }
                                else {
                                        $self->add_warning('No MySQL tables found for search hits.');
                                        $self->log->error('No tables found for result. tables: ' . Dumper($args->{node_info}->{nodes}->{$node}->{tables}));
                                        $cv->end; #end sphinx query
                                }
                        }, @sphinx_values);
                };

Original comment by edavi...@gmail.com on 16 Feb 2012 at 7:42

GoogleCodeExporter commented 9 years ago 
The "else }" is line 2662 for me.

Original comment by edavi...@gmail.com on 16 Feb 2012 at 7:42

GoogleCodeExporter commented 9 years ago 
Argh!  Ok, let's just make it dump tables regardless, after line 2615, put:

$self->log->debug('node: ' . Dumper($args->{node_info}->{nodes}->{$node}));

This should make it dump everything it knows about the node (indexes, tables, 
etc.).  We're looking to see why it thinks it doesn't have any tables for your 
results.

One other thing you can try that may shed some light: switch your query to 
"Archive" from "Index" using the button on the web UI.  Give it a minute or two 
after the query has been batched, and it should show up in "Saved Results" 
under the "ELSA" menu button in the top left corner of the screen.

Original comment by mchol...@gmail.com on 16 Feb 2012 at 7:51

GoogleCodeExporter commented 9 years ago 
Seems ELSA has consumed my hard drive.  How do I clear out space to continue?

Original comment by edavi...@gmail.com on 16 Feb 2012 at 10:13

GoogleCodeExporter commented 9 years ago 
Can I delete all of the temp_* files from /data/sphinx?

Original comment by edavi...@gmail.com on 16 Feb 2012 at 10:14

GoogleCodeExporter commented 9 years ago 
How about truncating the database tables as well and just starting from scratch?

Original comment by edavi...@gmail.com on 16 Feb 2012 at 10:17

GoogleCodeExporter commented 9 years ago 
Ah, running out of space may explain the weirdness you've been experiencing.  I 
suppose the canonical answer is that you need to set "log_size_limit" in the 
elsa_node.conf file down to a smaller number.  ELSA should never fill the drive 
if that number is smaller than the size of the partition.  Once you've changed 
the number to something that will fit, restarting syslog-ng should make it drop 
tables and indexes until the total files are smaller than "log_size_limit" size.

If you need to immediately clear space, the safest thing is to truncate 
database table syslog.indexes, as ELSA will then truncate all indexes and 
delete all MySQL index tables.

Original comment by mchol...@gmail.com on 17 Feb 2012 at 4:18

GoogleCodeExporter commented 9 years ago 
Ok, let me try this out and see if things get better.

Original comment by edavi...@gmail.com on 17 Feb 2012 at 8:23

GoogleCodeExporter commented 9 years ago 
Ok, trying again since it looks like the system is loading data once more ... 
Attached is the most recent web log for the word "traffic" which returned no 
results.

Original comment by edavi...@gmail.com on 17 Feb 2012 at 8:47

Attachments:

GoogleCodeExporter commented 9 years ago 
Can you verify that searchd is running?  If it is, try restarting it.  The lack 
of "meta" returned shows that the query didn't actually get a real result back 
at all from the searchd Sphinx index, so somehow it didn't get there.  You 
might want to try:
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE MATCH('traffic')"
again.

Original comment by mchol...@gmail.com on 17 Feb 2012 at 9:37

GoogleCodeExporter commented 9 years ago 
[root@elsa ~]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('traffic')"
+----------+--------+------------+-------+--------+----------+------------+-----
-------+----------+---------+---------+---------+---------+---------+---------+-
--------+---------+---------+---------+---------+---------+
| id       | weight | timestamp  | day   | hour   | minute   | host_id    | 
program_id | class_id | attr_i0 | attr_i1 | attr_i2 | attr_i3 | attr_i4 | 
attr_i5 | attr_s0 | attr_s1 | attr_s2 | attr_s3 | attr_s4 | attr_s5 |
+----------+--------+------------+-------+--------+----------+------------+-----
-------+----------+---------+---------+---------+---------+---------+---------+-
--------+---------+---------+---------+---------+---------+
| 50011216 |   1476 | 1329643318 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011217 |   1476 | 1329643318 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011218 |   1476 | 1329643318 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011219 |   1476 | 1329643318 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011220 |   1476 | 1329643318 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011221 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011222 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011223 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011224 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011225 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011226 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011227 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011228 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011229 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011230 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011231 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011232 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011233 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011234 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
| 50011235 |   1476 | 1329643319 | 15389 | 369345 | 22160722 | 2886740029 | 
1574083243 |        1 |       0 |       0 |       0 |       0 |       0 |       
0 |       0 |       0 |       0 |       0 |       0 |       0 |
+----------+--------+------------+-------+--------+----------+------------+-----
-------+----------+---------+---------+---------+---------+---------+---------+-
--------+---------+---------+---------+---------+---------+

Original comment by edavi...@gmail.com on 20 Feb 2012 at 3:51

GoogleCodeExporter commented 9 years ago 
Hard drive filled up again so I have reduced the log limit yet again, deleted 
the sphinx files and truncated the indexes tables.  Starting over ... will 
check that sphinx query in a bit and update when done.

Original comment by edavi...@gmail.com on 20 Feb 2012 at 3:59

GoogleCodeExporter commented 9 years ago 
I am getting this now when I try the mysql query:
# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE MATCH('traffic')"
ERROR 1064 (42000) at line 1: index perm_1: failed to open 
/data/sphinx/perm_1.spd: No such file or directory
The files in the /data/sphinx directory are named perm_1.new.sp? and would 
explain why it cannot find the file.  But, why would that be?

Original comment by edavi...@gmail.com on 21 Feb 2012 at 11:21

GoogleCodeExporter commented 9 years ago 
The .new extension means that the index file is ready to be rotated in by the 
searchd (Sphinx) daemon.  The fact that it's still there indicates that searchd 
is not running, or there was a problem in its startup.  Can you verify it's up? 
 If it is, try a service searchd restart.

Original comment by mchol...@gmail.com on 22 Feb 2012 at 5:05

GoogleCodeExporter commented 9 years ago 
Looks like I got around the .new issue and searchd is running.  Still no 
results but not loads of errors either.

[root@elsa log]# ps ax | grep search
 4515 pts/0    S      0:00 /usr/local/sphinx/bin/searchd --config /usr/local/etc/sphinx.conf
 4526 pts/0    S      0:00 /usr/local/sphinx/bin/searchd --config /usr/local/etc/sphinx.conf
 4532 pts/0    S      0:00 /usr/local/sphinx/bin/searchd --config /usr/local/etc/sphinx.conf
 4534 pts/0    S+     0:00 grep search
18310 pts/0    S      0:30 /usr/local/sphinx/bin/searchd --config 
/usr/local/etc/sphinx.conf
[root@elsa log]# tail searchd.log
[Wed Feb 22 11:33:19.360 2012] [18310] rotating index 'temp_1': success
[Wed Feb 22 11:33:19.360 2012] [18310] rotating finished
[Wed Feb 22 11:34:17.954 2012] [18310] rotating indices (seamless=1)
[Wed Feb 22 11:34:17.957 2012] [18310] WARNING: rotating index 'temp_1' without 
preopen option; use per-index propen=1 or searchd preopen_indexes=1
[Wed Feb 22 11:34:17.986 2012] [18310] rotating index 'temp_1': success
[Wed Feb 22 11:34:17.986 2012] [18310] rotating finished
[Wed Feb 22 11:35:18.029 2012] [18310] rotating indices (seamless=1)
[Wed Feb 22 11:35:18.033 2012] [18310] WARNING: rotating index 'temp_2' without 
preopen option; use per-index propen=1 or searchd preopen_indexes=1
[Wed Feb 22 11:35:19.067 2012] [18310] rotating index 'temp_2': success
[Wed Feb 22 11:35:19.068 2012] [18310] rotating finished

Original comment by edavi...@gmail.com on 22 Feb 2012 at 5:40

GoogleCodeExporter commented 9 years ago 
Ok, so this returns results now:
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE MATCH('traffic')"

But search the web interface yields nothing?  If so, what's in the web.log?

Original comment by mchol...@gmail.com on 22 Feb 2012 at 6:31

GoogleCodeExporter commented 9 years ago 
Nope.

[root@elsa log]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('allowed')"
[root@elsa log]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('internal')"
[root@elsa log]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('traffic')"

I do get a result with the following:

[root@elsa log]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('1')"
+------+--------+-----------+------+------+--------+---------+------------+-----
-----+---------+---------+---------+---------+---------+---------+---------+----
-----+---------+---------+---------+---------+
| id   | weight | timestamp | day  | hour | minute | host_id | program_id | 
class_id | attr_i0 | attr_i1 | attr_i2 | attr_i3 | attr_i4 | attr_i5 | attr_s0 
| attr_s1 | attr_s2 | attr_s3 | attr_s4 | attr_s5 |
+------+--------+-----------+------+------+--------+---------+------------+-----
-----+---------+---------+---------+---------+---------+---------+---------+----
-----+---------+---------+---------+---------+
|    1 |   1500 |         0 |    0 |    0 |      0 |       1 |          1 |     
   1 |       0 |       0 |       0 |       0 |       0 |       0 |       0 |    
   0 |       0 |       0 |       0 |       0 |
+------+--------+-----------+------+------+--------+---------+------------+-----
-----+---------+---------+---------+---------+---------+---------+---------+----
-----+---------+---------+---------+---------+

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:39

GoogleCodeExporter commented 9 years ago 
If you search for "seq" in the web interface, do you get anything?

Original comment by mchol...@gmail.com on 22 Feb 2012 at 6:41

GoogleCodeExporter commented 9 years ago 
web.log attached.

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:42

Attachments:

GoogleCodeExporter commented 9 years ago 
No results in web interface for 'seq'

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:42

GoogleCodeExporter commented 9 years ago 
[root@elsa log]# mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE 
MATCH('seq')"                   
[root@elsa log]#

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:43

GoogleCodeExporter commented 9 years ago 
What does it mean when there are 23780 hits and 23780 docs?  And how does that 
relate to a total of 0?

                      'hits[0]' => '23780',
                      'time' => '0.003',
                      'docs[0]' => '23780',
                      'keyword[0]' => 'traffic',
                      'total' => '0'

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:46

GoogleCodeExporter commented 9 years ago 
That usually means that the filters have filtered all of the hits out.  Can you 
try removing any time restrictions?

Original comment by mchol...@gmail.com on 22 Feb 2012 at 6:50

GoogleCodeExporter commented 9 years ago 
Oh, well that works now.  Used to give an error message if time fields were 
empty but even so, the start time was set to the default of "1969-12-29 
18:00:00".  I get 42 rows for "seq" and 62348 rows for "traffic".

Looks like there is a bug in the time calculation as a start time that far back 
should return everything.  But, now that I am getting some information, I have 
some more to work with.  Looks like I need some additional classes so I will 
submit them as separate issues.

Thanks for persisting with me on this "painful" issue.  I will keep an eye on 
this for anything you need to troubleshoot the start time problem.

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:54

GoogleCodeExporter commented 9 years ago 
Actually, if I put ANY time in the time filter, even for valid range that I can 
see without the filters, I get NO results.

Original comment by edavi...@gmail.com on 22 Feb 2012 at 6:56

GoogleCodeExporter commented 9 years ago 
Is the time correct on the machine you're using?  install.sh should set the 
time, but that's definitely something to look at.

Are the timestamps correct on the logs that are displayed?  Anything unique 
with timezones?

Original comment by mchol...@gmail.com on 22 Feb 2012 at 7:10

GoogleCodeExporter commented 9 years ago 
Time sync is good with nothing unusual about the timezone.  The log times are 
correct.

Original comment by edavi...@gmail.com on 22 Feb 2012 at 11:42

GoogleCodeExporter commented 9 years ago 
What does it show when you hover over the start time for "Earliest" and end 
time for "Latest?"  Also, what values are you putting in the fields to test 
with?

Original comment by mchol...@gmail.com on 23 Feb 2012 at 2:05

GoogleCodeExporter commented 9 years ago 
Earliest and Latest both show 1969-12-31 18:00:00.
I saw that my time showing on events in the list was Wed Feb 22 17:21:34 so I 
tried "2012-02-22 17:21:00" for From and "2012-02-22 17:22:00" for To.  
I tried this again today and I think I see why dates are not working when I put 
them in.  I had to really trim down the log limit to keep from running out of 
disk space and now it looks like the logs are cycling out every couple minutes 
so by the time the query results are sitting on the screen for a bit of time 
and I come back to try a time window, the logs I was looking at are already 
gone.  I am going to try to raise this limit again and see if I can get them to 
stick around a bit longer.

Original comment by edavi...@gmail.com on 23 Feb 2012 at 3:32

GoogleCodeExporter commented 9 years ago 
Wow, either you've got a very small amount of drive space or a very high log 
volume!  How much logs are you getting per minute and how often is it rolling 
them?  What do you have in syslog.v_indexes?

Original comment by mchol...@gmail.com on 23 Feb 2012 at 3:36

GoogleCodeExporter commented 9 years ago 
I do have a high volume of logs and the log limit is VERY low as I kept running 
out of space I made this very small.  I just increased it by a factor of 10 and 
will see how this helps.  This is a test system so the drive space is a bit 
limited right now but obviously this will be changed when I deploy.

mysql> select * from syslog.v_indexes;
+----+-----------+---------------------+---------------------+---------+--------
---+
| id | type      | start               | end                 | records | 
locked_by |
+----+-----------+---------------------+---------------------+---------+--------
---+
|  1 | temporary | 2012-02-23 09:18:21 | 2012-02-23 09:19:21 |    9380 |      
NULL |
|  9 | temporary | 2012-02-23 09:26:22 | 2012-02-23 09:27:22 |    9264 |      
NULL |
| 10 | temporary | 2012-02-23 09:27:22 | 2012-02-23 09:28:22 |    9469 |      
NULL |
| 11 | temporary | 2012-02-23 09:28:22 | 2012-02-23 09:29:22 |    8243 |      
NULL |
| 12 | temporary | 2012-02-23 09:29:22 | 2012-02-23 09:30:22 |   10768 |      
NULL |
| 13 | temporary | 2012-02-23 09:30:22 | 2012-02-23 09:31:22 |    8239 |      
NULL |
+----+-----------+---------------------+---------------------+---------+--------
---+
6 rows in set (0.00 sec)

Original comment by edavi...@gmail.com on 23 Feb 2012 at 4:05

GoogleCodeExporter commented 9 years ago 
Ah, that volume isn't too bad.  Each of our nodes does about 10k logs per 
second.  It must be the disk space allocated.  The big thing you'll want to 
make sure your test rig does is run through index consolidation so that the 
temporary indexes become permanent.  Consolidation occurs either when the 
number of possible temp indexes runs out, memory being used by the temp indexes 
is too high, or table size is hit (dictated by the config setting 
"perm_index_size" which is the number of logs to record before doing 
consolidation.  To have your box consolidate every 15 minutes, you could set 
that to something like 150000, which is much lower than the shipped default of 
10 million.

Original comment by mchol...@gmail.com on 23 Feb 2012 at 4:26

GoogleCodeExporter commented 9 years ago 
Ok, I will try 150000 and see what that does.

Original comment by edavi...@gmail.com on 23 Feb 2012 at 4:55

GoogleCodeExporter commented 9 years ago 
I am experiencing a very similar problem - my system is in a test environment 
with very low volume. 

I have worked through this thread and verified that incomming syslog data is 
showing up in syslog_data.syslogs_index_1 using the command "mysql -uroot 
SELECT * FROM syslog_data.syslogs_index_1".

I believe I've also verified that data is being processed by Sphinx by running  
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM temp_74 WHERE MATCH('MAC')" and  
mysql -h127.0.0.1 -P3307 -e "SELECT * FROM perm_1 WHERE MATCH('MAC')".  I'm not 
sure what the difference is between the perm files and the temp files - seems 
like the temp files get updated frequently and the perm files less 
frequently...a few hours it seems.  Most of the perm files have a size of 44 
but they all have the same timestamp.

When I attempt a search in the GUI everything ends up with a red Error and 
Query Failed. I've tried "seq", "class-none", "class=ANY", "MAC", "test" and 
others.  The MAC relates to an event from an iptables firewall, "test" related 
to connecting to UDP port 514 and typeing test and other things.

Original comment by jerrysh...@gmail.com on 9 Mar 2012 at 5:16

GoogleCodeExporter commented 9 years ago 
Ok, try searching for "seq" again and be sure to remove any time values.  You 
can verify that the time values are what's causing no results by checking 
/data/elsa/log/web.log and seeing that there are hits for "seq" in the Sphinx 
meta output but no "docs."  That means that it is finding results but filtering 
them due to time restraints.

Original comment by mchol...@gmail.com on 9 Mar 2012 at 7:13

GoogleCodeExporter commented 9 years ago 
With both time fields empty, there are still no results for a search for seq.  
Also, the web.log file doesn't get updated.  The last update there was from 
yeaterday at 17:39 - I had tested for seq yesterday and did get results back.  
I guess that means that I broke something;)  At that point, I wasn't getting 
any syslog data.

I should look at the ZZelsa.conf file in /etc/httpd/conf.d

Original comment by jerrysh...@gmail.com on 9 Mar 2012 at 7:29

GoogleCodeExporter commented 9 years ago 
I also have cacti and nagios running on this box an the VirtualHost setting for 
elsa was stomping on both of them so I set up a secondary IP address.  After 
swapping some syslog stuff around, I rebooted....the secondary IP address 
wasn't in any scripts...duhh....workin' like a charm now!

Original comment by jerrysh...@gmail.com on 9 Mar 2012 at 7:38