Some log entries missing after loading very old logs

[burkm]

Hello,

We've decided to send our Oracle log files to NLS. After writing a script and installing the Logstash HTTP plugin, we got it working.
Next, we decided to load a log that goes back to Oct 2013. I selected one month to view, Oct 2015. There were 688 log entries that month, but I only see 207 in NLS. The distribution of the log entries in NLS seems random, with some days having most of the entries and other days having none.

Ideas?

Thanks

[rkennedy]

Could you show us a sample of logs that appear in the log file, but not in NLS? Even the full log file with 688 entries may help, as I can try to replicate this on my end.

I'm wondering if it has to do with out things are parsing. Are these log files multiline at all? Does it line up with all the fields accordingly? Any additional information you can provide will be helpful, as it should be storing all of them.

[burkm]

Oracle logs are not pretty. A log entry consists of a timestamp in ctime format on a line by itself, followed by a multi-line message. The log entry ends where the next timestamp starts. Here's a sample of entries that were missed when loading:

Sat Oct 24 00:04:40 2015
Archived Log entry 4263 added for thread 1 sequence 4255 ID 0x28d7b59c dest 1:
Sat Oct 24 00:06:52 2015
Thread 1 cannot allocate new log, sequence 4257
Private strand flush not complete
Current log# 2 seq# 4256 mem# 0: /u01/oradata/cogrid12/redo02_a.log
Current log# 2 seq# 4256 mem# 1: /u00/oradata/cogrid12/redo02_b.log
Thread 1 advanced to log sequence 4257 (LGWR switch)
Current log# 3 seq# 4257 mem# 0: /u01/oradata/cogrid12/redo03_a.log
Current log# 3 seq# 4257 mem# 1: /u00/oradata/cogrid12/redo03_b.log
Sat Oct 24 00:07:05 2015
Archived Log entry 4264 added for thread 1 sequence 4256 ID 0x28d7b59c dest 1:
Sat Oct 24 01:00:10 2015
ALTER SYSTEM ARCHIVE LOG
Sat Oct 24 01:00:10 2015
Thread 1 advanced to log sequence 4258 (LGWR switch)
Current log# 1 seq# 4258 mem# 0: /u01/oradata/cogrid12/redo01_a.log
Current log# 1 seq# 4258 mem# 1: /u00/oradata/cogrid12/redo01_b.log
Sat Oct 24 01:00:13 2015
Archived Log entry 4265 added for thread 1 sequence 4257 ID 0x28d7b59c dest 1:
ALTER SYSTEM ARCHIVE LOG
Thread 1 cannot allocate new log, sequence 4259
Private strand flush not complete
Current log# 1 seq# 4258 mem# 0: /u01/oradata/cogrid12/redo01_a.log
Current log# 1 seq# 4258 mem# 1: /u00/oradata/cogrid12/redo01_b.log
Thread 1 advanced to log sequence 4259 (LGWR switch)
Current log# 2 seq# 4259 mem# 0: /u01/oradata/cogrid12/redo02_a.log
Current log# 2 seq# 4259 mem# 1: /u00/oradata/cogrid12/redo02_b.log
Archived Log entry 4266 added for thread 1 sequence 4258 ID 0x28d7b59c dest 1:
Sat Oct 24 02:00:00 2015
Closing scheduler window
Closing Resource Manager plan via scheduler window
Clearing Resource Manager plan via parameter
Sat Oct 24 06:00:00 2015
Setting Resource Manager plan SCHEDULER[0x318E]:DEFAULT_MAINTENANCE_PLAN via scheduler window
Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
Sat Oct 24 06:00:00 2015
Starting background process VKRM
Sat Oct 24 06:00:00 2015
VKRM started with pid=71, OS id=35729
Sat Oct 24 06:00:02 2015
Begin automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"
End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK"


I discovered that I need to escape the double quotes that appear in messages, so that explains a few of the missed messages.

I loaded about 26K log entries from one server, and got 221 out of 668.
Next I loaded just the 688 messages from another server (to be able to distinguish them), and got 545 messages, so there's a discrepancy there.

I'm wondering if loading the 26K at once caused some to be dropped?

[hsmith]

None of them should be missed. Can you show a screenshot of how the logs are showing up in your NLS dashboard? See if it can tell the the difference between where the logs start and stop. Multiline logs are super tricky.

[burkm]

Screen shot attached. The message portion is exactly as it appears in the log, and the timestamp is correct.

[hsmith]

How long of a timeperiod are you looking through for the logs? If you have a log file from December, and it came in today, you'll have to search for logs from December, they won't all show up like they came in new today.

[burkm]

I specified Oct 1 – Nov 1 2015 as the search range. See screen shot.
Also, notice the two different counts from different machines. For the same time period, those should match.

[hsmith]

What kind of input are you using on these logs? syslog?

[burkm]

I wrote a script to parse the logs, which seems to be working correctly. The parser constructs JSON code, which I then send to the Logstash HTTP plugin, using the JSON codec.

[hsmith]

That shouldn't have been required, but if it's working that's great. I'm wondering if logstash was dropping logs of a format it didn't like for the input you were using.