search

papertrail / remote_syslog2

To install, see "Releases" tab. Self-contained daemon for reading local files and emitting remote syslog (without using local syslogd).
http://help.papertrailapp.com/
MIT License
638 stars 157 forks source link

Missing Log Entries #167

Open CyborgMaster opened 8 years ago

CyborgMaster commented 8 years ago

Any time multiple lines are appended to the log close together, papertrail only gets some of them. If I can't figure this out, I'm going to have to consider moving to another service.

I'm using the recomended set up for elastic beanstalk using the .ebextensions file here: https://github.com/papertrail/remote_syslog2/blob/master/examples/remote_syslog.ebextensions.config, and my version is set to v0.17.

When I tail the log file directly on the server, I see this:

[2016-07-28T00:09:36.444139 #10758]  INFO [Stats] Running DailyStats from SWF.
[2016-07-28T00:09:36.444282 #10758]  INFO [Stats] Stubbed - Skipping
[2016-07-28T00:18:14.062370 #11234]  INFO [Stats] Running DailyStats from SWF.
[2016-07-28T00:18:14.062513 #11234]  INFO [Stats] Stubbed - Skipping
[2016-07-28T00:23:59.772819 #11547]  INFO [Stats] Running DailyStats from SWF.
[2016-07-28T00:23:59.772978 #11547]  INFO [Stats] Stubbed - Skipping
[2016-07-28T00:24:07.980573 #11565]  INFO [Stats] Running DailyStats from SWF.
[2016-07-28T00:24:07.980711 #11565]  INFO [Stats] Stubbed - Skipping
[2016-07-28T01:05:21.884176 #13911]  INFO Running the comm engine from SWF. Current date: 2016-07-28T01:05:00+00:00
[2016-07-28T01:05:21.884312 #13911]  INFO ------------------------------------------------------------
[2016-07-28T01:05:21.884334 #13911]  INFO Starting CommEngine
[2016-07-28T01:05:48.928765 #13911]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T01:05:48.928825 #13911]  INFO ------------------------------------------------------------
[2016-07-28T02:05:38.462349 #17294]  INFO Running the comm engine from SWF. Current date: 2016-07-28T02:05:00+00:00
[2016-07-28T02:05:38.462505 #17294]  INFO ------------------------------------------------------------
[2016-07-28T02:05:38.462531 #17294]  INFO Starting CommEngine
[2016-07-28T02:06:05.040441 #17294]  INFO CommEngine Finished.  Elapsed Time: 26
[2016-07-28T02:06:05.040501 #17294]  INFO ------------------------------------------------------------
[2016-07-28T03:05:38.422210 #20657]  INFO Running the comm engine from SWF. Current date: 2016-07-28T03:05:00+00:00
[2016-07-28T03:05:38.422330 #20657]  INFO ------------------------------------------------------------
[2016-07-28T03:05:38.422352 #20657]  INFO Starting CommEngine
[2016-07-28T03:06:06.047091 #20657]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T03:06:06.047152 #20657]  INFO ------------------------------------------------------------
[2016-07-28T04:05:36.448820 #24057]  INFO Running the comm engine from SWF. Current date: 2016-07-28T04:05:00+00:00
[2016-07-28T04:05:36.448967 #24057]  INFO ------------------------------------------------------------
[2016-07-28T04:05:36.448993 #24057]  INFO Starting CommEngine
[2016-07-28T04:06:03.410103 #24057]  INFO CommEngine Finished.  Elapsed Time: 26
[2016-07-28T04:06:03.410180 #24057]  INFO ------------------------------------------------------------
[2016-07-28T05:05:38.406085 #27464]  INFO Running the comm engine from SWF. Current date: 2016-07-28T05:05:00+00:00
[2016-07-28T05:05:38.406228 #27464]  INFO ------------------------------------------------------------
[2016-07-28T05:05:38.406272 #27464]  INFO Starting CommEngine
[2016-07-28T05:06:05.955976 #27464]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T05:06:05.956039 #27464]  INFO ------------------------------------------------------------
[2016-07-28T06:05:38.569014 #30833]  INFO Running the comm engine from SWF. Current date: 2016-07-28T06:05:00+00:00
[2016-07-28T06:05:38.569169 #30833]  INFO ------------------------------------------------------------
[2016-07-28T06:05:38.569197 #30833]  INFO Starting CommEngine
[2016-07-28T06:06:06.071618 #30833]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T06:06:06.071673 #30833]  INFO ------------------------------------------------------------
[2016-07-28T07:05:37.758102 #1740]  INFO Running the comm engine from SWF. Current date: 2016-07-28T07:05:00+00:00
[2016-07-28T07:05:37.758239 #1740]  INFO ------------------------------------------------------------
[2016-07-28T07:05:37.758262 #1740]  INFO Starting CommEngine
[2016-07-28T07:06:05.281828 #1740]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T07:06:05.281890 #1740]  INFO ------------------------------------------------------------
[2016-07-28T08:00:37.883342 #4827]  INFO [Stats] Running DailyStats from SWF.
[2016-07-28T08:00:37.883486 #4827]  INFO [Stats] Stubbed - Skipping
[2016-07-28T08:05:25.943758 #5170]  INFO Running the comm engine from SWF. Current date: 2016-07-28T08:05:00+00:00
[2016-07-28T08:05:25.943920 #5170]  INFO ------------------------------------------------------------
[2016-07-28T08:05:25.943955 #5170]  INFO Starting CommEngine
[2016-07-28T08:05:53.977286 #5170]  INFO CommEngine Finished.  Elapsed Time: 28
[2016-07-28T08:05:53.977347 #5170]  INFO ------------------------------------------------------------
[2016-07-28T09:05:36.424776 #8538]  INFO Running the comm engine from SWF. Current date: 2016-07-28T09:05:00+00:00
[2016-07-28T09:05:36.424947 #8538]  INFO ------------------------------------------------------------
[2016-07-28T09:05:36.424984 #8538]  INFO Starting CommEngine
[2016-07-28T09:06:03.800633 #8538]  INFO CommEngine Finished.  Elapsed Time: 27
[2016-07-28T09:06:03.800711 #8538]  INFO ------------------------------------------------------------
[2016-07-28T10:05:35.297769 #11990]  INFO Running the comm engine from SWF. Current date: 2016-07-28T10:05:00+00:00
[2016-07-28T10:05:35.297923 #11990]  INFO ------------------------------------------------------------
[2016-07-28T10:05:35.297956 #11990]  INFO Starting CommEngine
[2016-07-28T10:06:02.293771 #11990]  INFO CommEngine Finished.  Elapsed Time: 26
[2016-07-28T10:06:02.293833 #11990]  INFO ------------------------------------------------------------
[2016-07-28T11:05:35.432139 #15376]  INFO Running the comm engine from SWF. Current date: 2016-07-28T11:05:00+00:00
[2016-07-28T11:05:35.432287 #15376]  INFO ------------------------------------------------------------
[2016-07-28T11:05:35.432318 #15376]  INFO Starting CommEngine
[2016-07-28T11:06:02.421432 #15376]  INFO CommEngine Finished.  Elapsed Time: 26
[2016-07-28T11:06:02.421489 #15376]  INFO ------------------------------------------------------------

But papertrail only has this:

Jul 27 20:09:36 nova-background_i-60de5998 production.log:  [2016-07-28T00:09:36.444139 #10758]  INFO [Stats] Running DailyStats from SWF.
Jul 27 20:09:36 nova-background_i-60de5998 production.log:  [2016-07-28T00:09:36.444282 #10758]  INFO [Stats] Stubbed - Skipping
Jul 27 20:24:00 nova-background_i-60de5998 production.log:  [2016-07-28T00:23:59.772819 #11547]  INFO [Stats] Running DailyStats from SWF.
Jul 27 20:24:00 nova-background_i-60de5998 production.log:  [2016-07-28T00:23:59.772978 #11547]  INFO [Stats] Stubbed - Skipping
Jul 27 20:24:08 nova-background_i-60de5998 production.log:  [2016-07-28T00:24:07.980573 #11565]  INFO [Stats] Running DailyStats from SWF.
Jul 27 20:24:08 nova-background_i-60de5998 production.log:  [2016-07-28T00:24:07.980711 #11565]  INFO [Stats] Stubbed - Skipping
Jul 27 21:05:49 nova-background_i-60de5998 production.log:  [2016-07-28T01:05:48.928765 #13911]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 27 21:05:49 nova-background_i-60de5998 production.log:  [2016-07-28T01:05:48.928825 #13911]  INFO ------------------------------------------------------------
Jul 27 22:06:05 nova-background_i-60de5998 production.log:  [2016-07-28T02:06:05.040441 #17294]  INFO CommEngine Finished.  Elapsed Time: 26
Jul 27 22:06:05 nova-background_i-60de5998 production.log:  [2016-07-28T02:06:05.040501 #17294]  INFO ------------------------------------------------------------
Jul 27 23:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T03:06:06.047091 #20657]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 27 23:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T03:06:06.047152 #20657]  INFO ------------------------------------------------------------
Jul 28 00:06:03 nova-background_i-60de5998 production.log:  [2016-07-28T04:06:03.410103 #24057]  INFO CommEngine Finished.  Elapsed Time: 26
Jul 28 00:06:03 nova-background_i-60de5998 production.log:  [2016-07-28T04:06:03.410180 #24057]  INFO ------------------------------------------------------------
Jul 28 01:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T05:06:05.955976 #27464]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 01:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T05:06:05.956039 #27464]  INFO ------------------------------------------------------------
Jul 28 02:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T06:06:06.071618 #30833]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 02:06:06 nova-background_i-60de5998 production.log:  [2016-07-28T06:06:06.071673 #30833]  INFO ------------------------------------------------------------
Jul 28 03:06:05 nova-background_i-60de5998 production.log:  [2016-07-28T07:06:05.281828 #1740]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 03:06:05 nova-background_i-60de5998 production.log:  [2016-07-28T07:06:05.281890 #1740]  INFO ------------------------------------------------------------
Jul 28 04:05:26 nova-background_i-60de5998 production.log:  [2016-07-28T08:05:25.943758 #5170]  INFO Running the comm engine from SWF. Current date: 2016-07-28T08:05:00+00:00
Jul 28 04:05:26 nova-background_i-60de5998 production.log:  [2016-07-28T08:05:25.943920 #5170]  INFO ------------------------------------------------------------
Jul 28 04:05:26 nova-background_i-60de5998 production.log:  [2016-07-28T08:05:25.943955 #5170]  INFO Starting CommEngine
Jul 28 04:05:54 nova-background_i-60de5998 production.log:  [2016-07-28T08:05:53.977286 #5170]  INFO CommEngine Finished.  Elapsed Time: 28
Jul 28 04:05:54 nova-background_i-60de5998 production.log:  [2016-07-28T08:05:53.977347 #5170]  INFO ------------------------------------------------------------
Jul 28 05:06:04 nova-background_i-60de5998 production.log:  [2016-07-28T09:06:03.800633 #8538]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 05:06:04 nova-background_i-60de5998 production.log:  [2016-07-28T09:06:03.800711 #8538]  INFO ------------------------------------------------------------
Jul 28 06:06:02 nova-background_i-60de5998 production.log:  [2016-07-28T10:06:02.293771 #11990]  INFO CommEngine Finished.  Elapsed Time: 26
Jul 28 06:06:02 nova-background_i-60de5998 production.log:  [2016-07-28T10:06:02.293833 #11990]  INFO ------------------------------------------------------------
Jul 28 07:06:02 nova-background_i-60de5998 production.log:  [2016-07-28T11:06:02.421432 #15376]  INFO CommEngine Finished.  Elapsed Time: 26
Jul 28 07:06:02 nova-background_i-60de5998 production.log:  [2016-07-28T11:06:02.421489 #15376]  INFO ------------------------------------------------------------
Jul 28 08:06:16 nova-background_i-60de5998 production.log:  [2016-07-28T12:06:15.958981 #18756]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 08:06:16 nova-background_i-60de5998 production.log:  [2016-07-28T12:06:15.959043 #18756]  INFO ------------------------------------------------------------
Jul 28 09:06:04 nova-background_i-60de5998 production.log:  [2016-07-28T13:06:03.966806 #22108]  INFO CommEngine Finished.  Elapsed Time: 27
Jul 28 09:06:04 nova-background_i-60de5998 production.log:  [2016-07-28T13:06:03.966871 #22108]  INFO ------------------------------------------------------------
Jul 28 10:06:03 nova-background_i-60de5998 production.log:  [2016-07-28T14:06:03.106766 #25502]  INFO CommEngine Finished.  Elapsed Time: 26
Jul 28 10:06:03 nova-background_i-60de5998 production.log:  [2016-07-28T14:06:03.106841 #25502]  INFO ------------------------------------------------------------

As you can see over half of the entries are missing. It always seems to get at least one or two lines from each group of logs, but misses some as well.

snorecone commented 8 years ago

Hi @CyborgMaster I'm late to the party here, but if you're still using remote_syslog are you able to reproduce this issue with the latest version v0.19?

pridit commented 5 years ago

This is still happening. I am using the latest version v0.20. Two lines in my case that occurred on the same second, both completely ignored on Papertrail's end yet present physically in my file. I've had a feeling it was doing something like this as I am erroneously dropping logs elsewhere in a very similar fashion.

johlym commented 5 years ago

@pridit Two questions:

pridit commented 5 years ago

Thanks for the follow-up, to answer your questions:

Logs around this time all came through without issue, but specifically missed two that both occurred on the same second. The logs around the two in question were several minutes apart, so a sizeable gap. I had other logs that were a few seconds prior but I have my filter set to drop those particular ones, and I have confirmed the two logs I expected would not have been impacted by the filter.

I could enter forensic mode and begin isolating every single instance to determine if there's any pattern aside from what I have observed based on this issue, but that would of course take time (and based on the activity here wasn't sure whether it would ever be followed up). I had an initial feeling I was missing logs but never cross referenced with my file until now.

ibash commented 5 years ago

I'm using the papertrail add on in heroku and noticed the same problem. This makes the service a no-go.

pridit commented 5 years ago

Yep, I unfortunately can't afford to have logs dropping erroneously so won't be continuing, and this clearly isn't a priority for the team.