scribe syslog-ng and pppd

[robs]

Hello,

I have an Asus RT-AC86U with Merlin 386.2_6, scribe v2.4.3 from amtm

I think it would be great to have a separate pppd.log file in syslog-ng.
This is important to track past disconnections from the provider (and to debug them)

I wrote this file, it works but not entirely:
file /opt/etc/syslog-ng.d/pppd

destination d_pppd {
file("/opt/var/log/pppd.log");
};

filter f_pppd {
program("pppd")
};

log {
source(src);
filter(f_pppd);
destination(d_pppd);
flags(final);
};

#eof

now the log file /opt/var/log/pppd.log contains the pppd logs, but it lacks the first pppd connection on router startup
In other words, If I stop and start the connection from the WebUI it gets logged into /opt/var/log/pppd.log, but if I restart the router, the first connection gets logged into /opt/var/log/messages:

May 5 07:05:15 avahi-daemon[1781]: Alias name "RT-AC86U" successfully established.
May 5 07:05:15 custom_script: Running /jffs/scripts/services-start
May 5 07:05:15 scMerlin: Waiting for NTP to sync...
May 5 07:05:16 pppd[2023]: pppd 2.4.7 started by admin, uid 0
May 5 07:05:16 pppd[2023]: Connect: ppp0 <--> vlan835
May 5 07:05:16 kernel: SCSI subsystem initialized
May 5 07:05:17 kernel: scsi 0:0:0:0: Direct-Access Kingston DataTraveler 3.0 PMAP PQ: 0 ANSI: 6
May 5 07:05:17 kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
May 5 07:05:18 cfg_server: event: wl_chanspec_changed_action
May 5 07:05:18 cfg_server: skip event due static chan
May 5 07:05:19 pppd[2023]: CHAP authentication succeeded
May 5 07:05:19 pppd[2023]: peer from calling number A4:7B:2C:5A:9B:62 authorized
May 5 07:05:19 wsdd2[1902]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
May 5 07:05:19 wsdd2[1902]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
May 5 07:05:19 pppd[2023]: local IP address 151.40.xx.59
May 5 07:05:19 pppd[2023]: remote IP address 151.7.xx.15
May 5 07:05:19 pppd[2023]: primary DNS address 151.5.xx.150
May 5 07:05:19 pppd[2023]: secondary DNS address 151.5.xx.15

Any idea why this happens?

Thank you,
Roberto

 

[ColinTaylor]

I don't use scribe but it sounds like it's simply because scribe starts after the pppd interface has come up.

 

[robs]

I don't use scribe but it sounds like it's simply because scribe starts after the pppd interface has come up.

Yes a race condition ... but the log/messages file it's written entirely from the beginning and it is handled by syslog-ng.

How this happen ?

Regards,
Roberto

 

[ColinTaylor]

That's not really a race condition. If you're saying that Scribe is parsing other syslog entries made prior to when it starts then my theory is wrong and something else is causing the problem.

 

[JSewell]

but the log/messages file it's written entirely from the beginning and it is handled by syslog-ng.

Not exactly.

As Colin said, syslog-ng starts up after the pppd interface, so it won't catch the initial message on the router start-up.

The reason why messages appear in /opt/var/log/messages even though syslog-ng is not running is because Scribe installs a symbolic link linking the router's /tmp/syslog.log to the /opt/var/log/messages file.

So anything output to the system log is written there even without syslog-ng running.

 

[elorimer]

Close enough, maybe, but that isn't what happens.

1. The router starts logging immediately using syslogd, writing to /tmp/syslog.log. All the messages down to the start of entware are written there.
2. When entware starts running the the files in /opt/etc/init.d, S01syslog-ng in /opt/etc/init.d calls a prestart program, rc.func.syslog-ng.
3. The prestart program kills syslogd and klogd, so logging stops.
4. The prestart program then forms the symbolic link.
5. The prestart program copies everything in /tmp/syslog.log to the end of /opt/var/messages. You can tell where the restart is because those logged messages have the non-sync'ed time of May 5.
5. Then syslog-ng starts, first reading in its configurations and then starting to process the messages. At that point it will sort the messages into the filtered buckets, but it doesn't see any of the start up messages.

If you want, you can change rc.func.syslog-ng to write those startup messages to a file (call it "startup"). Then you can define a source being that file, and a filter/destination combo that runs first (by alphabet) that reads that file and sorts all of the startup messages (with a timestamp of when it processes the messages rather than May 5) into your buckets.