- Status Closed
- Percent Complete
- Task Type Bug Report
- Category Base system
- Assigned To No-one
- Operating System All
- Severity Low
- Priority Very Low
- Reported Version Trunk
- Due in Version Undecided
-
Due Date
Undecided
- Private
Attached to Project: OpenWrt/LEDE Project
Opened by anomeome - 04.04.2018
Last edited by Jo-Philipp Wich - 16.10.2018
Opened by anomeome - 04.04.2018
Last edited by Jo-Philipp Wich - 16.10.2018
FS#1468 - hostapd spams log
hostapd commit eba3b028 causes the log to be spammed if
option macfilter 'allow' list maclist 'xx:xx:xx:xx:xx:xx'
is used in wireless config stanza
I am not the originator of this ticket and am not sure of its intent, but can supply some initial testing results
It appears that hostapd does not respect the value set in, for example,
/var/run/hostapd-phy1.conf
and continues to log "info" level messages even though it appears that the proper log-level settings are present from the settings in/etc/config/wireless
I can't comment on if this is a change in behavior from the past as I manage my logging with
syslog-ng
and not by restricting the individual sources.OpenWrt SNAPSHOT, r6586+3-aed03d5
From
/var/run/hostapd-phy1.conf
From
hostapd.conf
in the upstream distributionEdit:
It looks like there are at least two code paths for logging in
hostap
, one throughwpa_printf()
and another throughwpa_auth_vlogger()
.The following issue is not reproducible using r6501-745d0e7f4b and is likely a software regression:
On r6671-f5195e72c0 hostapd handling of (Allow) MAC-ACL changed after commit eba3b028e4 and it is now over-flooding syslog with multiple "notice" messages per second (see quote):
Please note that authentication attempts of wifi-clients (Stations) not listed in the Allow MAC-ACL result in slightly different output in syslog (see quote):
All "Not allowed to authenticate" messages overflooding hostapd are not coupled with same-MAC "handle_auth_cb" messages; As far I understand this means hostapd spams syslog while no actual connection attempt is really occurring.
The log entries that brought this issue up in the forums appear to be expected 802.11 probe requests being rejected by
hostapd
as configured. In "busy" environments, users are interpreting this reporting of requested behavior as "spam".In my opinion, this should be resolved by allowing users to adjust the level of messages that appear in their log, not by removing the logging statement.
I took care to test a previous build (r6501-745d0e7f4b) and the spamming behavior in question is absent while the "busy" environment remains unchanged (as flashing require few minutes ow downtime tests were made few minutes apart)
Please note that if the "new behavior" introduced with commit eba3b028e4 is operating as intended, the entire syslog buffer will be filled by those entries in few hours.
In my opinion IF the previous hostapd version (2017-08-24) was not operating "as intended" it had to be purposely meant to prevent syslog spamming with unhelpful messages.
What would be the point to log rejected 802.11 probes like stated? Such amount of logspam should be caused by broadcast probes (many of those MAC I inspected belong to neighboring Access Points).
In previous hostapd version (2017-08-24) Enabling MAC-ACL(allow) would have syslog list only actual authentication attempt as follows
Both entries were added to syslog or none of them at all.
hostapd is an upstream project and widely used far beyond OpenWRT.
https://w1.fi/cgit
git blame
suggests that the change in behavior was introduced over a year agoThe author seems to come from a reputable organization
I am puzzled as to why it shows asdaemon.notice
and not "info" in the OpenWRT logs.The translation from
MSG_INFO
toLOG_NOTICE
occurs insrc/utils/wpa_debug.c
I disagree that the log messages are either "spam" or "unhelpful". In diagnosing a problem or resolving an incident, every log message can potentially be the one that provides the clue. Even in a busy environment, knowing what device had just failed to connect can make it much easier to determine which MAC to add, especially for devices that do not easily reveal their MAC to the user, or not at all (IoT devices, for example).
I do agree that OpenWRT users who use the ring-buffer logging system should be able to control the level of messages logged more easily than they can now. Determining why the upstream code suggests that these messages are to be logged as "info" and they appear as "notice" may provide further clues to resolving what is essentially a logging problem, not a functional one.
Edit
There also appear to be changes in
handle_probe_req()
in commit 92eb00ae that add to the puzzle as to why these are being logged at the "notice" level:The code path suggests that one should be seeing a log message from
ieee802_11_allowed_address()
at the info level, then one fromhandle_probe_req()
at the debug level.How much helpful would be an 802.11ad-behavior on non-802.11ad appliances?
Is it really technically unsound (or undesirable) to purposely disable such behavior on non-802.11ad modes?
Despite the 802.11ad usage scenario mentioned, this new behavior still remain unwarranted for all pre-802.11ad appliances in openwrt's table of hardware support.
Perhaps openwrt firmware download stats could be used to make a rough estimate of the ratio of potentially affected users (eg 802.11ad/non-802.11ad ratio)
PS: Hostapd version featured in build r6501-745d0e7f4b does still behave different
from the one in commit eba3b028e4; according to the makefile for r6501-745d0e7f4b hostapd had 2017-08-24 codebase. None of the neighboring MACs I inspected should have any reason to "probe" the tested (openwrt based) router SSID.
The probe is not directed, it is not probing your AP, in particular, but sending out a broadcast to discover available APs and their capabilities. This is a core part of the 802.11 stack. See https://documentation.meraki.com/MR/WiFi_Basics_and_Best_Practices/802.11_Association_process_explained as an example
Yes, it is very undesirable to permanently disable logging, as previously discussed. This should be handled with either the OpenWRT logger, or by "fixing" the OpenWRT patches that modify the
hostapd
logging so that UCI configuration can limit logging for OpenWRT users that use ring-buffer logging.@ari
Next time you build, try incorporating the attached patch. It should remove the
MSG_INFO
/LOG_NOTICE
message when responding to a probe request. It is untested.For a "proper" patch, it should be integrated with an appropriate UCI variable to enable/disable its logic dynamically (with a
reload_config
)Thanks.
The patch works as intended although I guessed is_probe_request was a typo and changed it to is_probe_req.
The comment from Dedy Lansky gave me the impression that his commit was meant specifically for 802.11ac modes but it doesn't appear the reason behind the new logging behavior.
I attempted a test build without most openwrt's hostapd patches (I included only nr. 100, 200, 300 and 600) but the excessive output remained.
It looks likely that the new behavior was introduced in hostapd after 2017-08-24 and before 2018-03-26.
Logging MAC rejections during 802.11 association phase would appear the only meaningful output for diagnostic of MAC-ACL operation.
I'm not an expert so I still don't understand what would be the point of logging broadcast probes if (allow)-MAC-ACL is used.
Since a wireless scanner on phones whose MAC is not ACL-allowed can detect the tested router SSID and encryption, it doesn't look like those probes are rejected.
Glad that could get you going – yes, I won't claim a typo, just a derp on my part.
It may well be that the phone app is just picking up the beacon frames that are periodically broadcast by the AP.
Knowing what stations are in range provide valuable information to the AP operator in a couple of ways. One is when one needs to reconfigure the AP to accept a "new" device. It's often much easier to see the device in the logs, than it is to try to wade through the device's secondary settings screens (especially with a device that the AP operator is not terribly familiar with), and may be nearly impossible with many embedded devices. As an example, there's no screen on an 802.11 light switch, and the MAC address is on a sticker, often buried in the back of the electrical box. Logging the events is also valuable when you believe that your AP should generally not be in range of "strange" devices, and want to know what unexpected devices might be in range.
On a "normal" system, these kinds of log messages can be filtered out into their own log, and that log managed appropriately. Without installing a different logging package, OpenWRT does not directly support this kind of log segmentation, at least that I am aware of. The patch supplied (and modified, as you indicate) the rejection should still be logged at the debug level, which is a noop unless enabled in the configuration of the compile of
hostap
sources. As I recall, the config parameter isWPA_MSG_MIN_PRIORITY
Thanks for the clarification.
While still retaining the old ability to report which unknown-MAC actually attempted to associate, the new behavior is akin to a proximity surveillance feature that would allow to estimate how long each unknown MACs was in range of the router and it could be probably used to track unknown-MAC movements in a WDS multi-AP area.
The new behavior was introduced by hostapd commit 92eb00ae just like you mentioned.
http://w1.fi/cgit/hostap/commit/?h=pending&id=92eb00aec2a05413a3b5da4982c488889d7f3bae
I'd like to add my 2 cents here, since this issue is very annoying.
I see two problems here:
1) Why is hostap logging this at the level notice in the first place? At least for probe requests that happen before a client actually tries to authenticate, this is not helpful. I do agree, that these may be helpful for debugging purposes, but certainly not always. I live in a city close to the center and my log is flooded with these messages at a rate of hundreds per minute as I have MAC address filtering enabled.
That may be discussed with the hostap folks but it's not the sole issue.
2) Why does the log_level option in config/wireless not allow to ignore these messages? Even if I set it to 4 which should *not* include the notice level, the message are still logged. Why is that the case? Is this some incompatibility between hostap and OpenWrt's logging daemon?
For now, as a temporary workaround, I've patched my build to simply log this particular message on the debug level. This way, they don't show up in my logs.
A
nd one note on Jeff's last comment: You say that with the patch supplied the message should still be logged at the debug level. Why is that? The only change is checking whether it's a probe request and if not, log it at info/notice level. Where does MSG_DEBUG come in?I understand now where debug logging comes in...Lastly, has anyone been in touch with upstream regarding this matter?
It should be fixed now in hostapd. So next time the code is pulled to OpenWrt it should be fixed here as well. See https://forum.openwrt.org/t/advice-needed-about-wifi-security/13188/85?u=m0urs
Patches cherry picked in https://git.openwrt.org/3e633bb3709611d79965fab667e3239fd3bde151