5 ms·

I don't have an ASUS router, but three things leap out at me: a string being logged over and over, running out of space on a filesystem, and rotated log files n

by JdeBP 3y ago

I don't have an ASUS router, but three things leap out at me: a string being logged over and over, running out of space on a filesystem, and rotated log files named something.1. It is trivially easy to blow right past the size capping on systems that use the old "newsyslog" style of external logfile rotation from the 20th century, and something that is logging a short string "[chknvram_action] Invalid string" over and over very fast is exactly how to do this. For those interested in investigation, therefore, I would suggest looking at logfile sizes, and seeing whether it was logs eating all of the free space on /jffs and /var . The underlying cause would be whatever is logging "[chknvram_action] Invalid string" thousands of times over, but the mechanism would be log files filling the tmpfs that the article mentions, which would explain why the system had no memory for forking new processes. My wild speculation about "[chknvram_action] Invalid string" is that something somewhere in whatever "chknvram" is, the name being suggestive of something checking non-volatile RAM, has either bad data or a broken parser, and the recovery semantics are to retry immediately, incessantly, as fast as possible.

bartvk 3y ago
Weird how syslog doesn't de-duplicate these identical log messages. Or maybe it does, but not enough.
- inferiorhuman 3y ago
  BSD syslogd definitely does, perhaps whatever stripped down one ASUS is using doesn't. e.g. Dec 2 01:09:41 hostname syslogd: last message repeated 10 times The threshold's pretty low and most of the "repeated" messages say "repeated 1 times" however.
  - TeMPOraL 3y ago
    Does it store timestamps for those repeated occurrences? I wouldn't want my logs to "helpfully" coalesce multiple identical messages into a single one. For example, if I saw the equivalent of the text below in a program/OS while facing some issues, I'd be remarkably pissed. [2023-05-18 07:12:21] [E] Invalid event 0x1AF2 received from ... [2023-05-18 09:44:01] [I] Last message repeated 10 times I care less about how many times the message was repeated - I care about timestamps, which I might want to correlate to other activities.
    - inferiorhuman 3y ago
      No, it's just a plain syslogd dating back to the 4.2 days. It aggregates at 30, 120, and 600 second intervals according to the source. Within that threshold I wouldn't care too much. If I really needed timestamps with more than thirty second precision I probably wouldn't be using syslogd. In any new-ish production system I'd probably want to use anything other than syslogd anyways. https://github.com/freebsd/freebsd-src/blob/main/usr.sbin/syslogd/syslogd.c https://github.com/freebsd/freebsd-src/blob/main/usr.sbin/sy...
      - TeMPOraL 3y ago
        That's... good to know. I never realized anyone is doing something like this, ever. It breaks my trust in software logs in general - I'll be sure from now on to understand how any given program handles logging, before making assumptions relevant to troubleshooting.
        kaliszad 3y ago
        In many cases, logs are asynchronous so depending on many factors among which are utilization of the host, you might get them with a delay and the ordering of events might not make sense because of that when read from the logs. If you need that precision you can surely engineer/ configure your system for that.
        TeMPOraL 3y ago
        If I'm running my own distributed system for some business reasons, sure. If I'm dealing with equipment failures, bugs in third-party software, or other such random tech bullshit, as an individual or a team, then I don't know in advance when and what precision I'll need.
        kaliszad 3y ago
        In a reasonable system, you might be able to change some function in one place, perhaps even in the running system and get the precision or detail you need. You might take out the big guns like e.g. dynamic tracing using BPF to attach probes at the right places.
  - throw0101c 3y ago
    > BSD syslogd definitely does …by default, but it can be disabled: -c Disable the compression of repeated instances of the same line into a single line of the form "last message repeated N times" when the output is a pipe to another program. If specified twice, disable this compression in all cases. * https://man.freebsd.org/cgi/man.cgi?query=syslogd https://man.freebsd.org/cgi/man.cgi?query=syslogd
- ricardobayes 3y ago
  Respectfully, logs shouldn't be "smart", they should just log, that's it.
- dfox 3y ago
  It seems that the binary in question just writes the logfile directly and does not use syslog.
JdeBP 3y ago
It turns out that chknvram is one part of the asd service, and it regularly downloads signature files looking for malwares. * https://www.snbforums.com/threads/what-is-asd-process.76242/#post-815090 https://www.snbforums.com/threads/what-is-asd-process.76242/... So some somewhat more informed speculation is that the new signature file either yesterday or today either broke a parser or was itself corrupt. The error-handling path for this is still poor.
- iforgotpassword 3y ago
  In the comments of the article someone mentions that deleting the file solved the issue without a firmware update. Too bad they didn't save it before, a comparison with the newer working version would be nice. I guess Asus quickly discovered their mistake and removed the faulty file from their servers, but affected devices never got to the point where they'd look for a newer file but just choked on the local one.
- denton-scratch 3y ago
  > it regularly downloads signature files Why does a router need malware signature files? It has no business monitoring my traffic, except in accordance with the firewall rules that I set myself. From the article: > not keeping my firmware up to date I've had this (non-Asus) router for three years. I've never updated the firmware.
  - unpopular42 3y ago
    > I've had this (non-Asus) router for three years. I've never updated the firmware. Botnet operators are very grateful for your cooperation, you are helping them a lot
    - vultour 3y ago
      I've never updated the firmware on any of my routers, and I'll be happy to give you a million dollars if you can prove that it's part of a botnet. This pathethic holier than thou attitude is obnoxious, you really think 95% of routers are part of a botnet? Or that they're even accessible from the internet?
checker 3y ago
What's your recommended alternative to the newsyslog style of external logfile rotation? I'm not much of a sysadmin but it might be useful to know at some point. Thanks in advance!
- JdeBP 3y ago
  The one that people came up with in the 1990s. There are quite a number of implementations to choose from. The shame of this hitting ASUS in 2023 is that this is a long-known problem and a long-since solved one. I have vague memories of grumpy posts on Usenet about this. It's that old a problem; and it has been solved for nigh on a quarter of a century. See https://jdebp.uk/FGA/do-not-use-logrotate.html https://jdebp.uk/FGA/do-not-use-logrotate.html for everything from Bryan Cantrill to comments in GNU source code. (-:
  - checker 3y ago
    Awesome, thanks! I am in fact guilty of using logrotate but thankfully I haven't been burned yet. Although perhaps with the advent of containers piping logs to streams I've unknowingly absolved myself. Also, you have an amazing website. Looking forward to reading more.

by JdeBP 3y ago

bartvk 3y ago

Weird how syslog doesn't de-duplicate these identical log messages. Or maybe it does, but not enough.

inferiorhuman 3y ago
BSD syslogd definitely does, perhaps whatever stripped down one ASUS is using doesn't. e.g. Dec 2 01:09:41 hostname syslogd: last message repeated 10 times The threshold's pretty low and most of the "repeated" messages say "repeated 1 times" however.
- TeMPOraL 3y ago
  Does it store timestamps for those repeated occurrences? I wouldn't want my logs to "helpfully" coalesce multiple identical messages into a single one. For example, if I saw the equivalent of the text below in a program/OS while facing some issues, I'd be remarkably pissed. [2023-05-18 07:12:21] [E] Invalid event 0x1AF2 received from ... [2023-05-18 09:44:01] [I] Last message repeated 10 times I care less about how many times the message was repeated - I care about timestamps, which I might want to correlate to other activities.
  - inferiorhuman 3y ago
    No, it's just a plain syslogd dating back to the 4.2 days. It aggregates at 30, 120, and 600 second intervals according to the source. Within that threshold I wouldn't care too much. If I really needed timestamps with more than thirty second precision I probably wouldn't be using syslogd. In any new-ish production system I'd probably want to use anything other than syslogd anyways. https://github.com/freebsd/freebsd-src/blob/main/usr.sbin/syslogd/syslogd.c https://github.com/freebsd/freebsd-src/blob/main/usr.sbin/sy...
    - TeMPOraL 3y ago
      That's... good to know. I never realized anyone is doing something like this, ever. It breaks my trust in software logs in general - I'll be sure from now on to understand how any given program handles logging, before making assumptions relevant to troubleshooting.
      - kaliszad 3y ago
        In many cases, logs are asynchronous so depending on many factors among which are utilization of the host, you might get them with a delay and the ordering of events might not make sense because of that when read from the logs. If you need that precision you can surely engineer/ configure your system for that.
        TeMPOraL 3y ago
        If I'm running my own distributed system for some business reasons, sure. If I'm dealing with equipment failures, bugs in third-party software, or other such random tech bullshit, as an individual or a team, then I don't know in advance when and what precision I'll need.
        kaliszad 3y ago
        In a reasonable system, you might be able to change some function in one place, perhaps even in the running system and get the precision or detail you need. You might take out the big guns like e.g. dynamic tracing using BPF to attach probes at the right places.
- throw0101c 3y ago
  > BSD syslogd definitely does …by default, but it can be disabled: -c Disable the compression of repeated instances of the same line into a single line of the form "last message repeated N times" when the output is a pipe to another program. If specified twice, disable this compression in all cases. * https://man.freebsd.org/cgi/man.cgi?query=syslogd https://man.freebsd.org/cgi/man.cgi?query=syslogd
ricardobayes 3y ago
Respectfully, logs shouldn't be "smart", they should just log, that's it.
dfox 3y ago
It seems that the binary in question just writes the logfile directly and does not use syslog.

JdeBP 3y ago

It turns out that chknvram is one part of the asd service, and it regularly downloads signature files looking for malwares. * https://www.snbforums.com/threads/what-is-asd-process.76242/#post-815090 https://www.snbforums.com/threads/what-is-asd-process.76242/... So some somewhat more informed speculation is that the new signature file either yesterday or today either broke a parser or was itself corrupt. The error-handling path for this is still poor.

iforgotpassword 3y ago
In the comments of the article someone mentions that deleting the file solved the issue without a firmware update. Too bad they didn't save it before, a comparison with the newer working version would be nice. I guess Asus quickly discovered their mistake and removed the faulty file from their servers, but affected devices never got to the point where they'd look for a newer file but just choked on the local one.
denton-scratch 3y ago
> it regularly downloads signature files Why does a router need malware signature files? It has no business monitoring my traffic, except in accordance with the firewall rules that I set myself. From the article: > not keeping my firmware up to date I've had this (non-Asus) router for three years. I've never updated the firmware.
- unpopular42 3y ago
  > I've had this (non-Asus) router for three years. I've never updated the firmware. Botnet operators are very grateful for your cooperation, you are helping them a lot
  - vultour 3y ago
    I've never updated the firmware on any of my routers, and I'll be happy to give you a million dollars if you can prove that it's part of a botnet. This pathethic holier than thou attitude is obnoxious, you really think 95% of routers are part of a botnet? Or that they're even accessible from the internet?

checker 3y ago

What's your recommended alternative to the newsyslog style of external logfile rotation? I'm not much of a sysadmin but it might be useful to know at some point. Thanks in advance!

JdeBP 3y ago
The one that people came up with in the 1990s. There are quite a number of implementations to choose from. The shame of this hitting ASUS in 2023 is that this is a long-known problem and a long-since solved one. I have vague memories of grumpy posts on Usenet about this. It's that old a problem; and it has been solved for nigh on a quarter of a century. See https://jdebp.uk/FGA/do-not-use-logrotate.html https://jdebp.uk/FGA/do-not-use-logrotate.html for everything from Bryan Cantrill to comments in GNU source code. (-:
- checker 3y ago
  Awesome, thanks! I am in fact guilty of using logrotate but thankfully I haven't been burned yet. Although perhaps with the advent of containers piping logs to streams I've unknowingly absolved myself. Also, you have an amazing website. Looking forward to reading more.