Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FS#1468 - hostapd spams log #6816

Closed
openwrt-bot opened this issue Apr 4, 2018 · 16 comments
Closed

FS#1468 - hostapd spams log #6816

openwrt-bot opened this issue Apr 4, 2018 · 16 comments
Labels

Comments

@openwrt-bot
Copy link

anomeome:

hostapd [[https://git.openwrt.org/?p=openwrt/openwrt.git;a=commit;h=eba3b028e46dbfe54f1208e9edf47bb0c6f73ac8|commit eba3b02]] causes the log to be spammed if
option macfilter 'allow'
list maclist 'xx:xx:xx:xx:xx:xx'

is used in wireless config stanza

[[https://forum.lede-project.org/t/advice-needed-about-wifi-security/13188/1|forum discussion]]

@openwrt-bot
Copy link
Author

jeffsf:

//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''
driver=nl80211
logger_syslog=127
logger_syslog_level=3
logger_stdout=127
logger_stdout_level=3

From ''hostapd.conf'' in the upstream distribution
# hostapd event logger configuration

Two output method: syslog and stdout (only usable if not forking to

background).

Module bitfield (ORed bitfield of modules that will be logged; -1 = all

modules):

bit 0 (1) = IEEE 802.11

bit 1 (2) = IEEE 802.1X

bit 2 (4) = RADIUS

bit 3 (8) = WPA

bit 4 (16) = driver interface

bit 5 (32) = IAPP

bit 6 (64) = MLME

Levels (minimum value for logged events):

0 = verbose debugging

1 = debugging

2 = informational messages

3 = notification

4 = warning

//Edit://

It looks like there are at least //two //code paths for logging in ''hostap'', one through ''wpa_printf()'' and another through ''wpa_auth_vlogger()''.

@openwrt-bot
Copy link
Author

arlit:

**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 [[https://git.openwrt.org/?p=openwrt/openwrt.git;a=commit;h=eba3b028e46dbfe54f1208e9edf47bb0c6f73ac8|commit eba3b02]] and it is now over-flooding syslog with multiple "notice" messages per second (see quote):

Thu Apr 12 15:53:20 2018 daemon.notice hostapd: Station BB:BB:BB:BB:BB:BB not allowed to authenticate
Thu Apr 12 15:53:20 2018 daemon.notice hostapd: Station CC:CC:CC:CC:CC:CC not allowed to authenticate
Thu Apr 12 15:53:20 2018 daemon.notice hostapd: Station DD:DD:DD:DD:DD:DD not allowed to authenticate

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):

Thu Apr 12 15:52:10 2018 daemon.notice hostapd: Station AA:AA:AA:AA:AA:AA not allowed to authenticate
Thu Apr 12 15:52:10 2018 daemon.notice hostapd: handle_auth_cb: STA AA:AA:AA:AA:AA:AA not found

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.

@openwrt-bot
Copy link
Author

jeffsf:

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.

@openwrt-bot
Copy link
Author

arlit:

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)

@openwrt-bot
Copy link
Author

arlit:

Please note that if the "new behavior" introduced with commit eba3b02 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

Thu Apr 12 15:52:10 2018 daemon.notice hostapd: Station AA:AA:AA:AA:AA:AA not allowed to authenticate
Thu Apr 12 15:52:10 2018 daemon.notice hostapd: handle_auth_cb: STA AA:AA:AA:AA:AA:AA not found

Both entries were added to syslog or none of them at all.

@openwrt-bot
Copy link
Author

jeffsf:

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 ago
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1596) if (res == HOSTAPD_ACL_REJECT) {
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1597) wpa_printf(MSG_INFO,
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1598) "Station " MACSTR " not allowed to authenticate",
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1599) MAC2STR(addr));
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1600) return HOSTAPD_ACL_REJECT;
53d17144 src/ap/ieee802_11.c (Dedy Lansky 2017-01-17 14:51:02 +0200 1601) }

The author seems to come from a reputable organization
Author: Dedy Lansky qca_dlansky@qca.qualcomm.com
Date: Tue Jan 17 14:51:02 2017 +0200

AP: Check ACL upon association request for 802.11ad

With device_ap_sme disabled, ACL was checked upon authentication
request. In 802.11ad there is no authentication phase so need to check
ACL upon association.

Signed-off-by: Dedy Lansky <qca_dlansky@qca.qualcomm.com>
I am puzzled as to why it shows as ''daemon.notice'' and not "info" in the OpenWRT logs.

The translation from ''MSG_INFO'' to ''LOG_NOTICE'' occurs in ''src/utils/wpa_debug.c''

static int syslog_priority(int level) { switch (level) { case MSG_MSGDUMP: case MSG_DEBUG: return LOG_DEBUG; case MSG_INFO: return LOG_NOTICE; case MSG_WARNING: return LOG_WARNING; case MSG_ERROR: return LOG_ERR; } return LOG_INFO; }

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:
+ ret = ieee802_11_allowed_address(hapd, mgmt->sa, (const u8 *) mgmt, len,

  •                                    &session_timeout,
    
  •                                    &acct_interim_interval, &vlan_id,
    
  •                                    &psk, &identity, &radius_cui, 1);
    
  •   if (ret == HOSTAPD_ACL_REJECT) {
    
  •           wpa_msg(hapd->msg_ctx, MSG_DEBUG,
    
  •                   "Ignore Probe Request frame from " MACSTR
    
  •                   " due to ACL reject ", MAC2STR(mgmt->sa));
    
  •           return;
    
  •   }
    

The code path suggests that one should be seeing a log message from '' ieee802_11_allowed_address()'' at the info level, then one from ''handle_probe_req()'' at the debug level.

@openwrt-bot
Copy link
Author

arlit:

**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 eba3b02; 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.

@openwrt-bot
Copy link
Author

jeffsf:

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

A mobile station sends probe requests to discover 802.11 networks within its proximity. Probe requests advertise the mobile stations supported data rates and 802.11 capabilities such as 802.11n. Because the probe request is sent from the mobile station to the destination layer-2 address and BSSID of ff:ff:ff:ff:ff:ff all AP's that receive it will respond.

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.

@openwrt-bot
Copy link
Author

jeffsf:

@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'')

@openwrt-bot
Copy link
Author

arlit:

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.

@openwrt-bot
Copy link
Author

jeffsf:

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 is ''WPA_MSG_MIN_PRIORITY''

@openwrt-bot
Copy link
Author

arlit:

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.

@openwrt-bot
Copy link
Author

arlit:

The new behavior was introduced by hostapd commit 92eb00ae just like you mentioned.
http://w1.fi/cgit/hostap/commit/?h=pending&id=92eb00aec2a05413a3b5da4982c488889d7f3bae

@openwrt-bot
Copy link
Author

silentcreek:

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.

And 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?

@openwrt-bot
Copy link
Author

m0urs:

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

@openwrt-bot
Copy link
Author

jow-:

Patches cherry picked in https://git.openwrt.org/3e633bb3709611d79965fab667e3239fd3bde151

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

1 participant