Scribe scribe - syslog-ng and logrotate installer

[cmkelley]

Don’t think this is related to scribe since I noticed this before installing. I noted that when viewing the syslog via the web GUI, it takes forever to load. Anyone else notice this?

Can you be more specific of what you mean by "takes forever to load"? Is there a long delay between an action, say SSHing into the router and that showing up in the log? Is it general slowness? Also what router, other scripts, etc. are you running?

 

[faria]

rt-ac86u.
I have been running this for 2 days with default config.
Even though all the log are written to var/ log , it stops updating the router System Log page about 2 minutes after its started or restarted.
Yesterday i waited 14 hours for the logs to reappear on System Log page but it never did.
I cant see a common cause, after rebooting the rooter it stops updating System Log page after loading QOS , next reboot , stopped a loading openvpn and just now just after loading Diversion.
@cmkelley Thanks for all your hard work, let me know if you need more info.

 

[elorimer]

I've been banging away at this and ended up last night not being able to start syslog-ng at all, so this morning I blew everything away. I deleted all of /syslog-ng.d, all of /logrotate.d, the S01 script, the conf files, the syslog-log files, the /jffs/syslog-log directories, reset the skynet custom location to default, rebooted and started fresh. I will note that this is on a 56U, so I'm stuck at 384.6.

I then did "scribe update" and got 0.5.5. Then I did "scribe install". I ended up roughly where @faria is, that is, syslogd exits, syslog-ng starts, at some point if syslog.log is a symlink it gets destroyed and recreated. messages continues to receive all syslog-ng messages, but syslog.log gets created from syslog.log-1 from somewhere and then stops.

I now have two important sources of failure, and one less important one.

The first is that skynet's location never got pointed to messages. I think that is what is creating syslog.log anew. Not sure why.

The second is that the symlink creation in rc.func.syslog-ng is never getting invoked. I put in a bunch of logger messages in there. I can see the file getting called the first time, and then exiting. So that will have formed the precmd string. Then I can see rc.func getting called, and I can see the precmd function starting and doing the kill_all. But the logger I put inside what runs if the symlink doesn't exist never is triggered. Creating the directories did work though.
Here's what I had

if [ ! -L "/tmp/syslog.log" ]; then
    logger -t rc.func.syslog-ng "starting forming symlink"
    cat /tmp/syslog.log >> /opt/var/log/messages
    rm /tmp/syslog.log /tmp/syslog.log-1
    ln -s /opt/var/log/messages /tmp/syslog.log
    logger -t rc.func.syslog-ng "finishing forming symlink"
    fi

Rebooting when no symlink existed didn't trigger either of those logger messages. So something about that if statement seems to be misfiring. I tried it with the ! outside the test brackets, too. I also tried replacing ! -L with -f, and that didn't work. But when I manually changed skynet's location, the prior symlinks held through a reboot.

The less important one is that when "I blew everything away" I forgot to do "opkg remove syslog-ng" and "opkg remove logrotate". So the scribe install got to the installation opkg saw they were installed and failed to do anything else.

 

[cmkelley]

I've been banging away at this and ended up last night not being able to start syslog-ng at all, so this morning I blew everything away. I deleted all of /syslog-ng.d, all of /logrotate.d, the S01 script, the conf files, the syslog-log files, the /jffs/syslog-log directories, reset the skynet custom location to default, rebooted and started fresh. I will note that this is on a 56U, so I'm stuck at 384.6.

I then did "scribe update" and got 0.5.5. Then I did "scribe install". I ended up roughly where @faria is, that is, syslogd exits, syslog-ng starts, at some point if syslog.log is a symlink it gets destroyed and recreated. messages continues to receive all syslog-ng messages, but syslog.log gets created from syslog.log-1 from somewhere and then stops.

I now have two important sources of failure, and one less important one.

The first is that skynet's location never got pointed to messages. I think that is what is creating syslog.log anew. Not sure why.

The second is that the symlink creation in rc.func.syslog-ng is never getting invoked. I put in a bunch of logger messages in there. I can see the file getting called the first time, and then exiting. So that will have formed the precmd string. Then I can see rc.func getting called, and I can see the precmd function starting and doing the kill_all. But the logger I put inside what runs if the symlink doesn't exist never is triggered. Creating the directories did work though.
Here's what I had

if [ ! -L "/tmp/syslog.log" ]; then
    logger -t rc.func.syslog-ng "starting forming symlink"
    cat /tmp/syslog.log >> /opt/var/log/messages
    rm /tmp/syslog.log /tmp/syslog.log-1
    ln -s /opt/var/log/messages /tmp/syslog.log
    logger -t rc.func.syslog-ng "finishing forming symlink"
    fi

Rebooting when no symlink existed didn't trigger either of those logger messages. So something about that if statement seems to be misfiring. I tried it with the ! outside the test brackets, too. I also tried replacing ! -L with -f, and that didn't work. But when I manually changed skynet's location, the prior symlinks held through a reboot.

The less important one is that when "I blew everything away" I forgot to do "opkg remove syslog-ng" and "opkg remove logrotate". So the scribe install got to the installation opkg saw they were installed and failed to do anything else.

Looks like "-! -L" isn't working the way I expected. I'll change that logic, getting ready to push a version with debugging.

 

[cmkelley]

I've been banging away at this and ended up last night not being able to start syslog-ng at all, so this morning I blew everything away. I deleted all of /syslog-ng.d, all of /logrotate.d, the S01 script, the conf files, the syslog-log files, the /jffs/syslog-log directories, reset the skynet custom location to default, rebooted and started fresh. I will note that this is on a 56U, so I'm stuck at 384.6.

I then did "scribe update" and got 0.5.5. Then I did "scribe install". I ended up roughly where @faria is, that is, syslogd exits, syslog-ng starts, at some point if syslog.log is a symlink it gets destroyed and recreated. messages continues to receive all syslog-ng messages, but syslog.log gets created from syslog.log-1 from somewhere and then stops.

I now have two important sources of failure, and one less important one.

The first is that skynet's location never got pointed to messages. I think that is what is creating syslog.log anew. Not sure why.

Do you get an error about skynet not existing? That's a strange one, I'll have to have a think about that.

The second is that the symlink creation in rc.func.syslog-ng is never getting invoked. I put in a bunch of logger messages in there. I can see the file getting called the first time, and then exiting. So that will have formed the precmd string. Then I can see rc.func getting called, and I can see the precmd function starting and doing the kill_all. But the logger I put inside what runs if the symlink doesn't exist never is triggered. Creating the directories did work though.
Here's what I had

if [ ! -L "/tmp/syslog.log" ]; then
    logger -t rc.func.syslog-ng "starting forming symlink"
    cat /tmp/syslog.log >> /opt/var/log/messages
    rm /tmp/syslog.log /tmp/syslog.log-1
    ln -s /opt/var/log/messages /tmp/syslog.log
    logger -t rc.func.syslog-ng "finishing forming symlink"
    fi

Rebooting when no symlink existed didn't trigger either of those logger messages. So something about that if statement seems to be misfiring. I tried it with the ! outside the test brackets, too. I also tried replacing ! -L with -f, and that didn't work. But when I manually changed skynet's location, the prior symlinks held through a reboot.

I think it's because the rm should be "rm -f", so I'll add that there.

The less important one is that when "I blew everything away" I forgot to do "opkg remove syslog-ng" and "opkg remove logrotate". So the scribe install got to the installation opkg saw they were installed and failed to do anything else.

It should have asked you if you wanted to force the installation if it found they were already installed.

 

[elorimer]

It should have asked you if you wanted to force the installation if it found they were already installed.

I think it asked me if I want to force reinstallation of scribe.

 

[cmkelley]

scribe v0.6_0 pushed

- debug info can be generated with "scribe debug", also generates tarball to PM
- added -f to rm statements, not sure what failure mechanism is if file isn't there, perhaps this is why symlinks aren't being created?
- now copies "syslog-ng.conf-small" to /opt/etc which;

• removes @include line that loads a slew of function
• sets maximum message size to 16K, probably overkill, but the 1K default was way too small
• sets stats frequency to every 6 hours
• stops logging from the local network (comments out function)
• adds a commented out function to log to the local network

 

[Butterfly Bones]

scribe v0.6_0 pushed

- debug info can be generated with "scribe debug", also generates tarball to PM
- added -f to rm statements, not sure what failure mechanism is if file isn't there, perhaps this is why symlinks aren't being created?
- now copies "syslog-ng.conf-small" to /opt/etc which;

• removes @include line that loads a slew of function
• sets maximum message size to 16K, probably overkill, but the 1K default was way too small
• sets stats frequency to every 6 hours
• stops logging from the local network (comments out function)
• adds a commented out function to log to the local network

Thank you, I am more than ready! I've been generating configs to clean and relog syslog entries. (fingers crossed they work). I'll wait to add them until this is running smoothly.
I was going to install this morning and then with the other comments, I knew to wait.

Two questions -
1 - where and how can the stats be seen?
2 - last bullet above, "adds a commented out function to log to the local network" that does not stop seeing the cleaned syslog in the webGUI does it? This is probably a dumb question, a little clarification for my overloaded brain, please.

 

[elorimer]

Rebooting when no symlink existed didn't trigger either of those logger messages. So something about that if statement seems to be misfiring.

Okay, way stupid of me. Nevermind. This immediately follows killing syslogd and before starting syslog-ng, so of course there isn't anything going to be logged.

 

[elorimer]

Do you get an error about skynet not existing? That's a strange one, I'll have to have a think about that.

Uninstalled scribe 0.5.5. Uninstalled some other bits too, noted below. Installed 0.6.0, completed install fine except for this, which I think is what you are looking for:

Configuring syslog-ng.
 setting up syslog-ng ... setting skynet log file location ...grep: /opt/etc/syslog-ng.d/skynet: No such file or directory
 done.

For the uninstall part, these were left behind:
1. the symlink for syslog.log
2. the S01 file in /init.d
3. the logrotate job
4. syslog-ng.conf in /etc

 

[cmkelley]

Thank you, I am more than ready! I've been generating configs to clean and relog syslog entries. (fingers crossed they work). I'll wait to add them until this is running smoothly.
I was going to install this morning and then with the other comments, I knew to wait.

Two questions -
1 - where and how can the stats be seen?
2 - last bullet above, "adds a commented out function to log to the local network" that does not stop seeing the cleaned syslog in the webGUI does it? This is probably a dumb question, a little clarification for my overloaded brain, please.

1) syslog-ng stats will be put in /opt/var/log/syslog-ng.log
2) no, if you have a remote log server, it's just the lines to send the logs to that remote server as well as store them locally.

 

[elorimer]

I had to chmod the S01 file, but everything seems to have come up as it should on a reboot with 0.6.0.

 

[cmkelley]

Uninstalled scribe 0.5.5. Uninstalled some other bits too, noted below. Installed 0.6.0, completed install fine except for this, which I think is what you are looking for:

Configuring syslog-ng.
 setting up syslog-ng ... setting skynet log file location ...grep: /opt/etc/syslog-ng.d/skynet: No such file or directory
 done.

For the uninstall part, these were left behind:
1. the symlink for syslog.log
2. the S01 file in /init.d
3. the logrotate job
4. syslog-ng.conf in /etc

1) maybe fixed with addition of -f to rm in 0.6, also changed delete logic in 0.6_1
2) fixed in 0.6_1
3) haven't been able to replicate
4) maybe fixed with addition of -f to rm in 0.6, also changed delete logic in 0.6_1

0.6_1 will be posted shortly, I'll post here when I do

 

[cmkelley]

I had to chmod the S01 file, but everything seems to have come up as it should on a reboot with 0.6.0.

Oh, FFS, I chmoded the wrong file in the installer. Good job.

 

[cmkelley]

Uninstalled scribe 0.5.5. Uninstalled some other bits too, noted below. Installed 0.6.0, completed install fine except for this, which I think is what you are looking for:

Configuring syslog-ng.
 setting up syslog-ng ... setting skynet log file location ...grep: /opt/etc/syslog-ng.d/skynet: No such file or directory
 done.

Ooops, I changed where skynet lives in the project, manged to fail to update the script. You'll find that skynet isn't being filtered with 0.6_1.

I just pushed v0.6_2 that fixes that, you should be able to scribe update.

 

[elorimer]

@Butterfly Bones, we're gonna make the pool safe for you. Jump in!

 

[L&LD]

@Butterfly Bones, we're gonna make the pool safe for you. Jump in!

I want to jump in too, but I'm 'scare'.

 

[Butterfly Bones]

@Butterfly Bones, we're gonna make the pool safe for you. Jump in!

I did and got bit. I had to do a full restore of my AC86U after it lost Internet access and refused SSH access.

Here is what I did to that point.

"scribe status"

Checking syslog-ng daemon...       dead.

"chmod 755 /opt/etc/init.d/S01syslog-ng"

"scribe restart"

Checking syslog-ng daemon...       dead.
 syslog-ng NOT running!  Starting syslog-ng ...
 Starting syslog-ng...              done.

Checked System Log, here are the last few lines.

Apr  5 15:51:33 kernel:  sda: sda1
Apr  5 15:51:33 kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk
Apr  5 15:51:33 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr  5 15:51:33 custom_script: Running /jffs/scripts/nat-start
Apr  5 15:51:33 (install_stubby.sh): 1819 Starting Script Execution (checkipv6)
Apr  5 15:51:33 rc_service: udhcpc 1218:notify_rc start_upnp
Apr  5 15:51:33 rc_service: waitting "stop_upnp" via udhcpc ...
Apr  5 15:51:34 disk_monitor: Finish
Apr  5 15:51:34 disk_monitor: be idle
Apr  5 15:51:34 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sda1 ) - max timeout = 120s
Apr  5 15:51:34 amtm: Running disk check 'e2fsck -p' on /dev/sda1
Apr  5 15:51:34 hotplug: USB ext4 fs at /dev/sda1 mounted on /tmp/mnt/SNB
Apr  5 15:51:34 usb: USB ext4 fs at /dev/sda1 mounted on /tmp/mnt/SNB.
Apr  5 15:51:34 kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: user_xattr
Apr  5 15:51:34 kernel: eth4 (Ext switch port: 3) (Logical Port: 11) Link UP 1000 mbps full duplex
Apr  5 15:51:34 kernel: br0: port 4(eth4) entered listening state
Apr  5 15:51:34 kernel: br0: port 4(eth4) entered listening state
Apr  5 15:51:34 custom_script: Running /jffs/scripts/post-mount (args: /tmp/mnt/SNB ) - max timeout = 120s
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPDISCOVER(br0) 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPOFFER(br0) 192.168.1.120 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPREQUEST(br0) 192.168.1.120 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPACK(br0) 192.168.1.120 50:c7:bf:fb:28:87 TPL-LB110
Apr  5 15:51:34 syslogd exiting

In about two more minutes as I looked at Skynet (log direction not pointed to syslog-ng only default) the webGUI got unresponsive and the Chrome window with the router just spun, could not move forward or back. I was able to get in with SSH ok, but none of the menu items in AMTM would respond, so I did
"system reboot".

After reboot I got into the webGUI but it was very unresponsive and very sluggish, taking 30-60 seconds to get to the next menu choice. I used the SSH to reboot again. Same thing, webGUI took long time to respond, so with SSH I did "scribe uninstall".

Next time the log in screen came up, I logged in and webGUI was worse, taking near 60 seconds to menu items, so I went to Admin and did a reset and reboot. When it came back up I restored the cfg file I made before I started this shenanigan.

 

[L&LD]

I did and got bit. I had to do a full restore of my AC86U after it lost Internet access and refused SSH access.

Here is what I did to that point.

"scribe status"

Checking syslog-ng daemon...       dead.

"chmod 755 /opt/etc/init.d/S01syslog-ng"

"scribe restart"

Checking syslog-ng daemon...       dead.
 syslog-ng NOT running!  Starting syslog-ng ...
 Starting syslog-ng...              done.

Checked System Log, here are the last few lines.

Apr  5 15:51:33 kernel:  sda: sda1
Apr  5 15:51:33 kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk
Apr  5 15:51:33 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr  5 15:51:33 custom_script: Running /jffs/scripts/nat-start
Apr  5 15:51:33 (install_stubby.sh): 1819 Starting Script Execution (checkipv6)
Apr  5 15:51:33 rc_service: udhcpc 1218:notify_rc start_upnp
Apr  5 15:51:33 rc_service: waitting "stop_upnp" via udhcpc ...
Apr  5 15:51:34 disk_monitor: Finish
Apr  5 15:51:34 disk_monitor: be idle
Apr  5 15:51:34 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sda1 ) - max timeout = 120s
Apr  5 15:51:34 amtm: Running disk check 'e2fsck -p' on /dev/sda1
Apr  5 15:51:34 hotplug: USB ext4 fs at /dev/sda1 mounted on /tmp/mnt/SNB
Apr  5 15:51:34 usb: USB ext4 fs at /dev/sda1 mounted on /tmp/mnt/SNB.
Apr  5 15:51:34 kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: user_xattr
Apr  5 15:51:34 kernel: eth4 (Ext switch port: 3) (Logical Port: 11) Link UP 1000 mbps full duplex
Apr  5 15:51:34 kernel: br0: port 4(eth4) entered listening state
Apr  5 15:51:34 kernel: br0: port 4(eth4) entered listening state
Apr  5 15:51:34 custom_script: Running /jffs/scripts/post-mount (args: /tmp/mnt/SNB ) - max timeout = 120s
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPDISCOVER(br0) 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPOFFER(br0) 192.168.1.120 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPREQUEST(br0) 192.168.1.120 50:c7:bf:fb:28:87
Apr  5 15:51:34 dnsmasq-dhcp[1357]: DHCPACK(br0) 192.168.1.120 50:c7:bf:fb:28:87 TPL-LB110
Apr  5 15:51:34 syslogd exiting

In about two more minutes as I looked at Skynet (log direction not pointed to syslog-ng only default) the webGUI got unresponsive and the Chrome window with the router just spun, could not move forward or back. I was able to get in with SSH ok, but none of the menu items in AMTM would respond, so I did
"system reboot".

After reboot I got into the webGUI but it was very unresponsive and very sluggish, taking 30-60 seconds to get to the next menu choice. I used the SSH to reboot again. Same thing, webGUI took long time to respond, so with SSH I did "scribe uninstall".

Next time the log in screen came up, I logged in and webGUI was worse, taking near 60 seconds to menu items, so I went to Admin and did a reset and reboot. When it came back up I restored the cfg file I made before I started this shenanigan.

Good use of a backup config file!

Only thing I would have done differently was to leave the router work out its issues (if it could) after that reboot. In the end, it may have amounted to the same thing (a full reset), but it would have still been interesting to see if it self-healed.

I'm going into the 'scribe - syslog-ng and logrotate' pool when Butterfly Bones does!

 

[Butterfly Bones]

Good use of a backup config file!

Only thing I would have done differently was to leave the router work out its issues (if it could) after that reboot. In the end, it may have amounted to the same thing (a full reset), but it would have still been interesting to see if it self-healed.

I'm going into the 'scribe - syslog-ng and logrotate' pool when Butterfly Bones does!

I'll be back in soon. I did not have time to let the router "settle" as I needed to respond to some urgent email requests for GPS data, watch games (I only stream TV), and I knew that I could do a full restore, since I do it fairly often and make one frequently and always before trying something beta like this.

Reading the previous messages, I see some fixes, and I want to contribute to the process. I'm reading thorough the recent commits on @cmkelley git to increase my confusion level this evening.

After dinner, I'll be jumping head first into the deep end.