OpenWrt/LEDE Project

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().

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

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.

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

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.

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.

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

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.

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

   quell-excess-probe-request-lo... (0.6 KiB)

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 is WPA_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.

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?

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