Problem description
I've meet a problem with one of my FreeBSD-wireless-router, and a FreeBSD network developer (Alexander V. Chernikov, alias melifaro) helps me to identify the culprit kernel function. I've write-down all tips I've learn by this teacher during this session here.
Day 1: Facing a bug
You need a bug for starting your day. In my case, after updating the configuration of previously working wireless-router, my setup stop working correctly.
Day 2: Reducing my setup complexity
My wireless-router configuration was complex: it involves routing, wireless in hostap mode, ipfw, snort, bridge, openvpn, etc.
The first step was to reproduce my problem:
- In the minimum steps (this mean with the simplest configuration)
- On the latest FreeBSD -current (because developers works on -current)
Rules for getting help: Your call-for-help message needs to be short, because developers don't have lot's of free time. It's very important that you clearly demonstrate a non-attended behavior and the steps for reproduce it easily.
I had to to it twice: I've post a first call-for-help message with a still too complex configuration:
https://lists.freebsd.org/pipermail/freebsd-current/2015-December/059045.html
Then I had to work again for simplify my problem and post a new message few days later:
https://lists.freebsd.org/pipermail/freebsd-current/2016-January/059250.html
This second message was a good one: It catch some developer eyes :-)
A resume of my bug with this setup:
LAN 0 <--> (re0) fbsd router (bridge0 = re1 + wlan0) <--> LAN 1 and Wireless LAN
This FreeBSD (11-head r293631) is configured like that:
- One IP address on re0, we will call this LAN 0
- One IP address on bridge0 (that includes interfaces re1 and wlan0)
- re1 enabled (put in UP state)
- wlan0 configured in hostap mode
- forwarding enabled
But this setup can forward between wireless clients and hosts on LAN 0 ONLY if interface re1 (that belong to bridge0) is in "connected" status !?!
If the Ethernet NIC is in "not connected" status, the FreeBSD router will consider all clients behind bridge0 "unreacheable"… Even if it can ping all wireless clients!
Here is a tcpdump output from the router dumping a ping generated by a wireless clients (1.1.1.2, connected to wlan0 and forwarded by cbridge0) toward an host on LAN 0 (1.0.0.2):
root@fbsd-router:~ # tcpdump -pni re0
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on re0, link-type EN10MB (Ethernet), capture size 262144 bytes
23:38:04.466866 ARP, Request who-has 1.0.0.2 tell 1.0.0.1, length 28
23:38:04.467052 ARP, Reply 1.0.0.2 is-at 00:08:a2:09:c4:a2, length 46
23:38:04.467090 IP 1.1.1.2 > 1.0.0.2: ICMP echo request, id 72, seq 1,length 64
23:38:04.467226 IP 1.0.0.2 > 1.1.1.2: ICMP echo reply, id 72, seq 1, length 64
23:38:04.467300 IP 1.0.0.1 > 1.0.0.2: ICMP host 1.1.1.2 unreachable, length 36
23:38:05.483053 IP 1.1.1.2 > 1.0.0.2: ICMP echo request, id 72, seq 2,length 64
23:38:05.483259 IP 1.0.0.2 > 1.1.1.2: ICMP echo reply, id 72, seq 2, length 64
23:38:05.483318 IP 1.0.0.1 > 1.0.0.2: ICMP host 1.1.1.2 unreachable, length 36
23:38:06.387304 IP 1.1.1.2 > 1.0.0.2: ICMP echo request, id 72, seq 3,length 64
23:38:06.387466 IP 1.0.0.2 > 1.1.1.2: ICMP echo reply, id 72, seq 3, length 64
23:38:06.387514 IP 1.0.0.1 > 1.0.0.2: ICMP host 1.1.1.2 unreachable, length 36
^C
For solving this problem, I just need to plug the Ethernet interface for changing its status to "active".
Checking interface status: a simple user's way
The only check I can do was to check the "status" of my interfaces:
root@fbsd-router# ifconfig re0
re0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=8209b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,WOL_MAGIC,LINKSTATE>
ether 00:0d:b9:3c:ae:24
inet 1.0.0.1 netmask 0xffffff00 broadcast 1.0.0.255
nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
media: Ethernet autoselect (1000baseT <full-duplex,master>)
status: active
root@fbsd-router# ifconfig wlan0
wlan0: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> metric 0 mtu 1500
ether 04:f0:21:17:3b:d7
nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
media: IEEE 802.11 Wireless Ethernet autoselect mode 11ng <hostap>
status: running
ssid tutu channel 6 (2437 MHz 11g ht/40+) bssid 04:f0:21:17:3b:d7
country US ecm authmode OPEN privacy OFF txpower 27 scanvalid 60
protmode CTS ampdulimit 64k ampdudensity 8 shortgi wme burst
dtimperiod 1 -dfs
groups: wlan
root@fbsd-router# ifconfig re1
re1: flags=8943<UP,BROADCAST,RUNNING,PROMISC,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=82099<RXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,WOL_MAGIC,LINKSTATE>
ether 00:0d:b9:3c:ae:25
nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
media: Ethernet autoselect (none)
status: no carrier
root@fbsd-router# ifconfig bridge0
bridge0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
ether 02:6b:c0:de:b8:00
inet 1.1.1.1 netmask 0xffffff00 broadcast 1.1.1.255
nd6 options=9<PERFORMNUD,IFDISABLED>
groups: bridge
id 00:00:00:00:00:00 priority 32768 hellotime 2 fwddelay 15
maxage 20 holdcnt 6 proto rstp maxaddr 2000 timeout 1200
root id 00:00:00:00:00:00 priority 32768 ifcost 0 port 0
member: re1 flags=143<LEARNING,DISCOVER,AUTOEDGE,AUTOPTP>
ifmaxaddr 0 port 2 priority 128 path cost 55
member: wlan0 flags=143<LEARNING,DISCOVER,AUTOEDGE,AUTOPTP>
ifmaxaddr 0 port 5 priority 128 path cost 33333
Nothing seems wrong here:
- re0 has flag UP and status "active"
- wlan0 has flag UP and status "running" (I will suppose it's okay because wireless clients paquets correctly enter this interface and even ping bridge0 IP address)
- re1 has flag UP and status "no carrier" (no cable connected)
- bridge0 has flag UP but did not display its status (I will suppose it's UP because wireless client can ping it)
But a developer will never "suppose" the status of these interfaces and will speak in their strange language directly to the kernel for asking the real status.
Checking kernel interface status: a developer's way
How FreeBSD kernel manage network interface ? As a simple user, let's read the (huge) "man ifconfig". I didn't found my answer, but the "see also" section mention a "man netintro".
An introduction to "network" should be comprehensive for me.
Inside netintro man page, I've skipped addressing and routing sections for the interfaces section, but nothing here about "interface status". But the "see also" section mention a "man ifnet": Let's try!
Trying to resume this man page:
(...)
The kernel mechanisms for handling network interfaces reside primarily in
the ifnet, if_data, ifaddr, and ifmultiaddr structures in <net/if.h> and
<net/if_var.h> and the functions named above and defined in
/sys/net/if.c.
(...)
The system keeps a linked list of interfaces using the TAILQ macros
defined in queue(3); this list is headed by a struct ifnethead called
ifnet. The elements of this list are of type struct ifnet...
(...)
The structure additionally contains generic statistics applicable to a
variety of different interface types (except as noted, all members are of
type u_long):
ifi_link_state (u_char) The current link state of Ethernet
interfaces. See the Interface Link States
section for possible values.
(...)
Interface Link States
The following link states are currently defined:
LINK_STATE_UNKNOWN The link is in an invalid or unknown state.
LINK_STATE_DOWN The link is down.
LINK_STATE_UP The link is up.
Wow, I reach my limits ;-) But here is my understanding:
- Each network interface have an index number assigned
- once known this index number we can read its state by variable ifi_link_state
I've got 3 new questions now :-(
How to know the "index" number of my interfaces ?
User used to uses "netstat -i" should know the "Link#" displayed:
root@fbsd-router:~ # netstat -iWW | grep Link# | tr -s ' ' | cut -d ' ' -f 1-3
re0 1500 <Link#1>
re1 1500 <Link#2>
re2* 1500 <Link#3>
lo0 16384 <Link#4>
wlan0 1500 <Link#5>
bridge0 1500 <Link#6>
This link number is the interface index number :-)
How to display this variable (ifi_link_state) ?
This answer came from melifaro@ : "use kernel debugger (kgdb) for printing value of variable called ifindex_table[INDEX].if_link_state".
How did this wizzard of code find variable ifindex_table[] ?
I had to use "grep ifindex_table /usr/src/sys/net/*" and found that ifindex_table is defined in if.c as "Table of ifnet by index."Reading the source code is mandatory here for discovering this variable name.
Why variable is if_link_state and not ifi_link_state like written in ifnet(9) ?
It seems that ifnet(9) (the manual page) is not up-to-date.Time to play with live kernel debugging
root@fbsd-router:~ # kgdb /boot/kernel/kernel /dev/mem
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
(...)
(kgdb) print ifindex_table[1].if_link_state
$1 = 2 '\002'
(kgdb) p ifindex_table[2].if_link_state
$2 = 1 '\001'
(kgdb) p ifindex_table[5].if_link_state
$3 = 0 '\0'
(kgdb) p ifindex_table[6].if_link_state
$4 = 1 '\001'
Great: I've got some values!
We can even print the full structure with command "ptype":
(kgdb) ptype ifindex_table[1]
type = struct ifnet {
struct {
struct ifnet *tqe_next;
struct ifnet **tqe_prev;
} if_link;
struct {
struct ifnet *le_next;
struct ifnet **le_prev;
} if_clones;
struct {
struct ifg_list *tqh_first;
struct ifg_list **tqh_last;
} if_groups;
u_char if_alloctype;
void *if_softc;
void *if_llsoftc;
void *if_l2com;
const char *if_dname;
int if_dunit;
u_short if_index;
short if_index_reserved;
char if_xname[0];
char *if_description;
int if_flags;
int if_drv_flags;
int if_capabilities;
int if_capenable;
void *if_linkmib;
size_t if_linkmiblen;
u_int if_refcount;
uint8_t if_type;
uint8_t if_addrlen;
uint8_t if_hdrlen;
uint8_t if_link_state;
uint32_t if_mtu;
uint32_t if_metric;
uint64_t if_baudrate;
uint64_t if_hwassist;
(...)
Funny but useless for my current task.
Another "grep LINK_STATE /usr/src/sys/net/*" for the answer: they are described in if.h:
/*
* Values for if_link_state.
*/
#define LINK_STATE_UNKNOWN 0 /* link invalid/unknown */
#define LINK_STATE_DOWN 1 /* link is down */
#define LINK_STATE_UP 2 /* link is up */
Now I can translate the "kernel view" of my interfaces:
What?!! Wait a minute: bridge0 is in state DOWN ?!? This can't be correct because my wlan0 interface is working!
The bridge logic seems to be wrong: If the first interface is in DOWN state, and the second in UNKNOW state, then bridge is in DOWN state.
Let's check by plugging re1 and testing the "kernel view" again:
(kgdb) p ifindex_table[2].if_link_state
$6 = 2 '\002'
(kgdb) p ifindex_table[6].if_link_state
$7 = 2 '\002'
Confirmed: once re1 switch to "LINK UP" state, the bridge switch to "LINK UP" too!!
There is definitively a bug in the bridge logic here, full detailed explanation here:
https://lists.freebsd.org/pipermail/freebsd-current/2016-January/059274.html
But I was not able, as simple user, to found by myself the exact index table name and variable name to debug :-(
Could I did it with D-trace ?
Dtrace guide (http://dtrace.org/guide/preface.html) mention:
"DTrace is a comprehensive dynamic tracing framework for the illumos™ Operating System. DTrace provides a powerful infrastructure to permit administrators, developers, and service personnel to concisely answer arbitrary questions about the behavior of the operating system and user programs"
=> As a "service personnel" I should be able to use it ;-)
First "freebsd dtrace" google answer is: https://wiki.freebsd.org/DTrace/Tutorial
This tutorial explains how to display all available dtrace probes… but what is a probe?
"A probe is a location or activity to which DTrace can bind a request to perform a set of actions, like recording a stack trace, a timestamp, or the argument to a function. Probes are like programmable sensors scattered all over your illumos system in interesting places." (for official guide).
For my "link state" problem, I will start by searching probes named "link_state" or "linkstate":
root@fbsd-router# dtrace -l | grep 'link.*state'
ID PROVIDER MODULE FUNCTION NAME
16563 fbt kernel do_link_state_change entry
16564 fbt kernel do_link_state_change return
16740 fbt kernel vlan_link_state entry
43390 fbt kernel if_link_state_change entry
43391 fbt kernel if_link_state_change return
53619 fbt kernel usbd_req_set_port_link_state entry
53620 fbt kernel usbd_req_set_port_link_state return
55751 fbt if_bridge bridge_linkstate entry
55825 fbt bridgestp bstp_linkstate entry
55826 fbt bridgestp bstp_linkstate return
There are some interesting results. But before to use them I had to read the dtrace guide:
"dtrace use D programming language for scripting action when probe are triggered."
As example, if I want to display "dtrace probe triggered" each time the dtrace proble "bridge_linkstate" is triggered, I can use this command:
dtrace -f 'bridge_linkstate {trace("dtrace probe triggered")}'
Here is an example:
root@fbsd-router:~ # dtrace -f 'bridge_linkstate {trace("dtrace probe triggered")}'
dtrace: description 'bridge_linkstate ' matched 1 probe
=> now I plug re1 interface to a switch
(kgdb) ptype ifindex_table[1]
type = struct ifnet {
struct {
struct ifnet *tqe_next;
struct ifnet **tqe_prev;
} if_link;
struct {
struct ifnet *le_next;
struct ifnet **le_prev;
} if_clones;
struct {
struct ifg_list *tqh_first;
struct ifg_list **tqh_last;
} if_groups;
u_char if_alloctype;
void *if_softc;
void *if_llsoftc;
void *if_l2com;
const char *if_dname;
int if_dunit;
u_short if_index;
short if_index_reserved;
char if_xname[0];
char *if_description;
int if_flags;
int if_drv_flags;
int if_capabilities;
int if_capenable;
void *if_linkmib;
size_t if_linkmiblen;
u_int if_refcount;
uint8_t if_type;
uint8_t if_addrlen;
uint8_t if_hdrlen;
uint8_t if_link_state;
uint32_t if_mtu;
uint32_t if_metric;
uint64_t if_baudrate;
uint64_t if_hwassist;
(...)
Funny but useless for my current task.
How to convert link_state values in Human language ?
Another "grep LINK_STATE /usr/src/sys/net/*" for the answer: they are described in if.h:
/*
* Values for if_link_state.
*/
#define LINK_STATE_UNKNOWN 0 /* link invalid/unknown */
#define LINK_STATE_DOWN 1 /* link is down */
#define LINK_STATE_UP 2 /* link is up */
Now I can translate the "kernel view" of my interfaces:
- re0 (index 1) is in state 2 (UP)
- re1 (index 2) is in state 1 (DOWN)
- wlan0 (index 5) is in state 0 (UNKNOWN)
- bridge0 (index 6) is in state 1 (DOWN)
What?!! Wait a minute: bridge0 is in state DOWN ?!? This can't be correct because my wlan0 interface is working!
The bridge logic seems to be wrong: If the first interface is in DOWN state, and the second in UNKNOW state, then bridge is in DOWN state.
Let's check by plugging re1 and testing the "kernel view" again:
(kgdb) p ifindex_table[2].if_link_state
$6 = 2 '\002'
(kgdb) p ifindex_table[6].if_link_state
$7 = 2 '\002'
Confirmed: once re1 switch to "LINK UP" state, the bridge switch to "LINK UP" too!!
There is definitively a bug in the bridge logic here, full detailed explanation here:
https://lists.freebsd.org/pipermail/freebsd-current/2016-January/059274.html
But I was not able, as simple user, to found by myself the exact index table name and variable name to debug :-(
Could I did it with D-trace ?
Checking kernel interface status: modern's way
Dtrace guide (http://dtrace.org/guide/preface.html) mention:
"DTrace is a comprehensive dynamic tracing framework for the illumos™ Operating System. DTrace provides a powerful infrastructure to permit administrators, developers, and service personnel to concisely answer arbitrary questions about the behavior of the operating system and user programs"
=> As a "service personnel" I should be able to use it ;-)
First "freebsd dtrace" google answer is: https://wiki.freebsd.org/DTrace/Tutorial
This tutorial explains how to display all available dtrace probes… but what is a probe?
"A probe is a location or activity to which DTrace can bind a request to perform a set of actions, like recording a stack trace, a timestamp, or the argument to a function. Probes are like programmable sensors scattered all over your illumos system in interesting places." (for official guide).
For my "link state" problem, I will start by searching probes named "link_state" or "linkstate":
root@fbsd-router# dtrace -l | grep 'link.*state'
ID PROVIDER MODULE FUNCTION NAME
16563 fbt kernel do_link_state_change entry
16564 fbt kernel do_link_state_change return
16740 fbt kernel vlan_link_state entry
43390 fbt kernel if_link_state_change entry
43391 fbt kernel if_link_state_change return
53619 fbt kernel usbd_req_set_port_link_state entry
53620 fbt kernel usbd_req_set_port_link_state return
55751 fbt if_bridge bridge_linkstate entry
55825 fbt bridgestp bstp_linkstate entry
55826 fbt bridgestp bstp_linkstate return
There are some interesting results. But before to use them I had to read the dtrace guide:
"dtrace use D programming language for scripting action when probe are triggered."
As example, if I want to display "dtrace probe triggered" each time the dtrace proble "bridge_linkstate" is triggered, I can use this command:
dtrace -f 'bridge_linkstate {trace("dtrace probe triggered")}'
Here is an example:
root@fbsd-router:~ # dtrace -f 'bridge_linkstate {trace("dtrace probe triggered")}'
dtrace: description 'bridge_linkstate ' matched 1 probe
=> now I plug re1 interface to a switch
CPU ID FUNCTION:NAME
1 55751 bridge_linkstate:entry dtrace probe triggered
=> now I unplug re1 interface
1 55751 bridge_linkstate:entry dtrace probe triggered
=> now I plug-back re1
1 55751 bridge_linkstate:entry dtrace probe triggered
=> now I unplug re1 interface
1 55751 bridge_linkstate:entry drace probe triggered
(...)
I've remove the other lines, because I've play with this cable during about 1 hour :-)
I can see when this probe was triggered…but I have no idea of the variable values changed (or not) before and after this call, then this information is almost useless.
Here came melifaro@ again that brings me a full dtrace script (I've added the comments):
/* The BEGIN is a special probe triggered at the begining of the script
The purpose here is to define a table giving link_state value=>description
*/
BEGIN {
a[0] = "UNKNOWN";
a[1] = "DOWN";
a[2] = "UP";
}
/* Defining an action when probe if_bridge:bridge_linkstate:entry is triggered
Notice that each probe had an :entry and :return
and entry or return variable are called "arg0"
If you need the return code of the function, :return is used
*/
fbt:if_bridge:bridge_linkstate:entry
{
/* Need to read sys/net/if_bridge.c for understanding this dtrace function
bridge_linkstate() is called with an ifnet structure pointer as argument (arg0).
First step is to cast arg0 into ifnet struct for using it: this->m_ifp
But we can't directly use this->m_ifp->if_link_state, because as a bridge interface,
this ifnet struct includes a specific "software state for each bridge"
(bridge_softc struct) as if_bridge.
Second step is to cast this->m_ifp->if_bridge into a bridge_softc struct: this->sc
The first member of a bridge_softc struc is a standard ifnet structure nammed ifp.
Then, at last, we cast ifnet struct on it: self->ifp
Now we can get the if_link_state with self->ifp->if_link_state
*/
this->m_ifp = (struct ifnet *)arg0;
this->sc = (struct bridge_softc *)this->m_ifp->if_bridge;
self->ifp = (struct ifnet *)this->sc->sc_ifp;
}
/* Defining an action when probe kernel:do_link_state_change is triggered
Notice the /self->ifp/
This is specific to D language that didn't include control flow (like if, while,).
Then here, each time this probe is triggered, the condition between / is checked.
If false (=0), code is not exectuted.
Here the condition is self->ifp, this mean this condition is triggered only if
this variable was set (non NULL) by the previous probe.
*/
fbt:kernel:do_link_state_change:entry
/self->ifp/
{
/* originaly a stack trace was displayed but I've commented it
stack();
*/
/* Need to read sys/net/if.c for understanding this dtrace function
static void do_link_state_change(void *arg, int pending)
the first argument (arg0) is an ifnet structure, the second argument is the "new" state to apply
*/
printf("linkstate changed for %s to %s", stringof(self->ifp->if_xname),
a[self->ifp->if_link_state]);
/* Then reset the triggering variable to NULL */
self->ifp = NULL;
}
Let's try it:
root@fbsd-router:~ # dtrace -s bridge.d
dtrace: script 'bridge.d' matched 3 probes
=> now I plug re1:
CPU ID FUNCTION:NAME
0 16563 do_link_state_change:entry linkstate changed for bridge0 to UP
=> now I unplug re1:
1 16563 do_link_state_change:entry linkstate changed for bridge0 to DOWN
=> now I plug re1 again:
1 16563 do_link_state_change:entry linkstate changed for bridge0 to UP
^C
Great, this tool give "live" view of my REAL current interface status from the kernel point of view.
For using Dtrace, like with kgbd, I had to read FreeBSD sources (man page is outdated here).
For this small "easy" troubleshooting, kgbd is a lot's more easy and faster choice.
But it's too late: I've started to read FreeBSD source code and learned how to use Dtrace now :-)
Small bugs, beware I'm coming!
