For quite a while test-runner has run into frequent OOM exceptions when
running many tests in a row. Its not completely known exactly why, but
seems to point to the 9p driver which is used for sharing the root fs
between the test-runner VM and the host.
With debugging enabled (-d) one can see the available memory available
relatively stable. If a test fails it may spike ~3-4kb but this quickly
recovers as python garbage collects.
At some point the kernel faults failing to allocate which (usually) is
shown by a python OOM exception. At this point there is plenty of
available memory.
Dumping the kernel trace its seen that the 9p driver is involved:
[ 248.962949] test-runner: page allocation failure: order:7, mode:0x40dc0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null),cpuset=/,mems_allowed=0
[ 248.962958] CPU: 2 PID: 477 Comm: test-runner Not tainted 5.16.0 #91
[ 248.962960] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-4.fc34 04/01/2014
[ 248.962961] Call Trace:
[ 248.962964] <TASK>
[ 248.962965] dump_stack_lvl+0x34/0x44
[ 248.962971] warn_alloc.cold+0x78/0xdc
[ 248.962975] ? __alloc_pages_direct_compact+0x14c/0x1e0
[ 248.962979] __alloc_pages_slowpath.constprop.0+0xbfe/0xc60
[ 248.962982] __alloc_pages+0x2d5/0x2f0
[ 248.962984] kmalloc_order+0x23/0x80
[ 248.962988] kmalloc_order_trace+0x14/0x80
[ 248.962990] v9fs_alloc_rdir_buf.isra.0+0x1f/0x30
[ 248.962994] v9fs_dir_readdir+0x51/0x1d0
[ 248.962996] ? __handle_mm_fault+0x6e0/0xb40
[ 248.962999] ? inode_security+0x1d/0x50
[ 248.963009] ? selinux_file_permission+0xff/0x140
[ 248.963011] iterate_dir+0x16f/0x1c0
[ 248.963014] __x64_sys_getdents64+0x7b/0x120
[ 248.963016] ? compat_fillonedir+0x150/0x150
[ 248.963019] do_syscall_64+0x3b/0x90
[ 248.963021] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 248.963024] RIP: 0033:0x7fedd7c6d8c7
[ 248.963026] Code: 00 00 0f 05 eb b7 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 f3 0f 1e fa b8 ff ff ff 7f 48 39 c2 48 0f 47 d0 b8 d9 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 01 c3 48 8b 15 81 a5 0f 00 f7 d8 64 89 02 48
[ 248.963028] RSP: 002b:00007ffd06cd87e8 EFLAGS: 00000293 ORIG_RAX: 00000000000000d9
[ 248.963031] RAX: ffffffffffffffda RBX: 000056090d87dd20 RCX: 00007fedd7c6d8c7
[ 248.963032] RDX: 0000000000080000 RSI: 000056090d87dd50 RDI: 000000000000000f
[ 248.963033] RBP: 000056090d87dd50 R08: 0000000000000030 R09: 00007fedc7d37af0
[ 248.963035] R10: 00007fedc7d7d730 R11: 0000000000000293 R12: ffffffffffffff88
[ 248.963038] R13: 000056090d87dd24 R14: 0000000000000000 R15: 000056090d0485e8
Here its seen an allocation of 512k is being requested (order:7), but faults.
In this run it there was ~35MB of available memory on the system.
Available Memory: 35268 kB
Last Test Delta: -2624 kB
Per-test Usage:
[ 0] ** 37016
[ 1] ********* 41584
[ 2] * 36280
[ 3] ********* 41452
[ 4] ******** 40940
[ 5] ****** 39284
[ 6] **** 38348
[ 7] *** 37496
[ 8] **** 37892
[ 9] 35268
This can be reproduced by running all autotests (changing the ram down to
~128MB helps trigger it faster):
./tools/test-runner -k <kernel> -d
After many attempts to fix this it was finally found that simply removing the
explicit 9p2000.u version from the kernel command line 'fixed' the problem.
This even allows decreasing the RAM down to 256MB from 384MB and so far no
OOM's have been seen.
In debug mode the test context is printed before each test. This
adds some additional information in there:
Available Memory: /proc/meminfo: MemAvailable
Last Test Delta: Change in usage between current and last test
Per-test Usage: Graph of usage relative to all past tests. This is
useful for seeing a trend down/up of usage.
Running the tests inside a VM makes it difficult for the host to figure
out if the test actually failed or succeeded. For a human its easy to
read the results table, but for an automated system parsing this would
be fragile. This adds a new option --result <file> which writes PASS/FAIL
to the provided file once all tests are completed. Any failures results in
'FAIL' being written to the file.
Currently CreateRadio only allows a single outstanding DBus message
until the radio is fully created. 99% of the time this is just fine
but in order to test dual phy cards there needs to be support for
phy's appearing at the same time.
This required storing the pending DBus message inside the radio object
rather than a single static variable.
The code was refactored to handle the internal radio info objects better
for the various cases:
- Creation from CreateRadio()
- Radio already existed before hwsim started, or created externally
- Existing radio changed name, address, etc.
First, Name is now a required option to CreateRadio(). This allows
the radio info to be pushed to the queue immediately (also allowing the
pending DBus message to be tracked). Then, when the NEW_RADIO event
fires the pending radio can be looked up (by name) and filled with the
remaining info.
If the radio was not found by name but a matching ID was found this is
the 'changed' case and the radio is re-initialized with the changed
values.
If neither name or ID matches the radio was created externally, or
prior to hwsim starting. A radio info object is created at this time
and initialized.
The ID was changed to a signed integer in order to initialize it to an
invalid number -1. Doing this was required since a pending uninitalized
radio ID (0) could match an existing radio ID. This required some
bounds checks in case the kernels counter reaches an extremely high value.
This isn't likely to ever happen in practice.
This tool will decrypt an IWD network profile which was previously
encrypted using a systemd provided key. Either a text passphrase
can be provided (--pass) or a file containing the secret (--file).
This can be useful for debugging, or recovering an encrypted
profile after enabling SystemdEncrypt.
This is created by the python interpreter for speed optimization
but poses problems if copied to /tmp since previous tests may
have already copied it leading to an exception.
Right now hwsim blindly tries to forward broadcast/multicast frames to
all interfaces it knows about and relies on the kernel to reject the
forwarding attempt if the frequency does not match. This results in
multiple copies of the same message being added to the genl transmit
queue.
On slower systems this can cause a run-away memory consumption effect
where the queued messages are not processed in time prior to a new
message being received for forwarding. The likelyhood of this effect
manifesting itself is directly related to the number of hostapd
instances that are created and are beaconing simultaneously.
Try to optimize frame forwarding by not sending beacon frames
to those interfaces that are in AP mode (i.e. pure hostapd instances)
since such interfaces are going to be operating on a different frequency
and would not be interested in processing beacon frames anyway.
This optimization cuts down peak memory use during certain tests by 30x
or more (~33mb to ~1mb) when profiled with 'valgrind --tool=massif'
It appears different versions of pyroute2 may or may not have
iwutil, and instead use pyroute2.IW() directly. Try the iwutil
way first, then pyroute2.IW()
After namespaces were added, the dbus address was customized to
be /tmp/dbus{0..N}. This prevented any dbus applications started
in the shell from working properly.
Set DBUS_SYSTEM_BUS_ADDRESS to the environment prior to entering
the shell.
If set, a rule will start matching 'MatchBytes' some number of bytes
into the frame (MatchBytesOffset). This is useful since header
information, addresses, and sequence numbers may be unpredictable
between test runs.
To avoid unintended matches the Prefix property is left unchanged
and will match starting at the beginning of the frame.
The hwsim rules did not treat frames and ACKs any differently which
can mislead the developer especially when setting a rule prefix.
If a prefix was used the frame ACK was actually being matched against
the original frame payload which seems wrong because the ACK is not
the original frame.
Though strange, matching the frame prefix on an ACK has its place if
the developer wants to block just the ACK rather than the frame so
to make this case more clear 'DropAck' was added as a rule property.
And only if this is true will an ACK be checked and potentially
dropped.
To maintain the current hwsim behavior DropAck will default to true.
This integer property can be set to only match a rule a number of
times rather than all packets. This is useful for testing behavior
of a single dropped frame or ack. Once the rule has been matched
'MatchTimes' the rules will no longer be applied (unless set again
to some integer greater than zero).
Since Process.processes is a weak reference dictionary any process
put in this dict will disappear if all references are lost. This
is much better than keeping a list in the Namespace which will hold
the references forever until test-runner manually kills them all at
the end of the test. This does still need to be done for daemon
processes but everything else can just go away when it is no longer
needed.
The test-runner logging is very basic and just dumps everything into files
per-test. This means any subtests are just appended to existing log files
which can be difficult to parse after the fact. This is especially hard
when IWD/Hostapd runs once for the entirety of the test (as opposed to
killing between tests).
This patch writes out a separator between each subtests in the form:
===== <file>:<function> =====
To do this all processes are now kept as weak references inside the
Process class itself. Process.write_separators() can be called which
will iterate through all running processes and write the provided
separator.
This also paves the way to remove the ctx.processes array which is more
trouble than its worth due to reference issues.
Note: For tests which start IWD this will have no effect as the separator
is written prior to the test running. For these tests though, it is
much easier to read the log files because you can clearly see when
IWD starts and exits.
Processes which were not explicitly killed ended up staying around
forever because they internally held references to other objects
such as GLib IO watches or write FDs.
This shuffles some code so these objects get cleaned up both when
explititly killed and after being waited for.
This was a placeholder at one point but modules grew to depend on it
being a string. Fix these dependencies and set the root namespace
name to None so there is no more special case needed to handle both
a named namespace and the original 'root' namespace.
Check whether verbose output is enabled for process name arg[0] before
prepending the "ip netns exec" part to arg since arg[0] is going to be
"ip" after that.
These modules only needed to be imported a single time for the entire
run of tests. This is significantly cheaper in terms of memory and
should prevent random OOM exceptions.
The Procss class was doing quite a bit of what Popen already does like
storing the return code and process arguments. In addition the Process
class ended up storing a Popen object which was frequently accessed.
For both simplicity and memory savings have Process inherit Popen and
add the additional functionality test-runner needs like stdout
processing to output files and the console.
To do this Popen.wait() needed to be overridden to to prevent blocking
as well as wait for the HUP signal so we are sure all the process
output was written. kill() was also overritten to perform cleanup.
The most intrusive change was removing wait as a kwarg, and instead
requiring the caller to call wait(). This doesn't change much in
terms of complexity to the caller, but simplifies the __init__
routine of Process.
Some convenient improvements:
- Separate multiple process instance output (Terminate: <args> will
be written to outfiles each time a process dies.)
- Append to outfile if the same process is started again
- Wait for HUP before returning from wait(). This allows any remaining
output to be written without the need to manually call process_io.
- Store ctx as a class variable so callers don't need to pass it in
(e.g. when using Process directly rather than start_process)
This was initially put in to solve an issue that was specific to
mac80211_hwsim where the connect callback would get queued and
delayed until after the connect event. This caused IWD to get very
confused.
Later it was found that "real" drivers can sometimes do this so
some code was added to IWD core to handle it.
Now there isn't much point to delay all frames unless a rule specifies
so change the behavior back to sending out frames immediately.
The hwsim Rule API was structured as properties so once a rule is
created it automatically starts being applied to frames. This happens
before anything has time to actually define the rule (source, destination
etc). This leads to every single frame being matched to the rule until
these other properties are added, which can result in unexpected behavior.
To fix this an "Enabled" property has been added and the rule will not
be applied until this is true.
The -S/--sub-tests option allows the user to specify a test file
from inside an autotest. Inside this file there may also be many
test functions. This option is being extended to allow running
a single test function inside a test file. For example:
* Runs all test functions inside connection_test.py *
./test-runner -A some_test -S connection_test
* Runs only connection_test.py test_connect_success() *
./test-runner -A some_test -S connection_test.test_connect_success
There was a race condition here where the GLib timeout could have
fired but the test function returned successfully prior to the
end of the while loop. This would end up causing source_remove to
print a warning that the source did not exist.
Instead check if the timeout fired prior to removing it.
This addresses the TODO where HostapdCLI was creating separate
objects each time HostapdCLI was called. This was worked around
by manually setting the important members but instead the class
can be re-worked to act as somewhat of a singleton, per-config
at least.
If there is no HostapdCLI instance for a given config one is
created and initialized. Subsequent HostapdCLI calls (for the
same config) will be returned the same object rather than a
new one.
Tests that called skipTest would result in an exception which would
hault execution as it was uncaught. In addition this wouldn't result
in an skipped test.
Now the actual test run is surrounded in a try/except block, skipped
exceptions are handled specifically, and a stack trace is printed if
some other exception occurs.
dmesg was being called at the very end of testing and dumped into
a log file. If many tests were run this could take quite a long
time and was timing out the default process wait. Instead --follow
can be used (basically like 'tail') which prints messages as they
come and avoids the time consuming full dump at the end.
There was a common bit of code all over test-runner and utilities
which would wait for 'something' in a loop. At best these loops
would do the right thing and use the GLib.iteration call as to not
block the main loop, and at worst would not use it and just busy
wait.
Namespace.non_block_wait unifies all these into a single API to
a) do the wait correctly and b) prevent duplicate code.
While losing the convenience of unittest this patch breaks out
each individual test function in order to run it manually and
get results. This vastly improves the user experience by seeing
which test file and function is being executed rather than simply
seeing "PASSED" for the entire test set.
In addition exceptions/failures are printed out as they happen
rather than at the end.
With the addition of connect_bssid/roam very few tests actually
require hwsim. Since hwsim can lead to problems with scan results
its best to have it off by default and have each test that needs
it explicitly turn it on.
Tests which previously turned it off have had that option removed.
Tests that do require hwsim still are vulnerable to scan result
problems, so for these tests beacon_int was added to the hostapd
config which seems to help with reliability somewhat.
If a test has no hw.conf file test-runner was fully exiting and not
running any additional tests. This shouldn't happen in practice
since all upstreamed tests should run, but if any locally created
tests existed like this, it would cause the entire test run to exit
early.
Instead raise an exception which bails out of only that test, and
allows the rest to continue.
The Process class requires the ability to write out any processes
output to stdout, logging, or an explicit file, as well as store
it inside python for processing by test utilities. To accomplish
this each process was given a temporary file to write to, and that
file had an IO watch set on it. Any data that was written was then
read, and re-written out to where it needed to go. This ended up
being very buggy and quite complex due to needing to mess with
read/write pointers inside the file.
Popen already creates pipes to stdout if told, and they are accessable
via the p.stdout. Its then as simple as setting an IO watch on that
pipe and keeping the same code for reading out new data and writing
it to any files we want. This greatly reduces the complexity.
Occationally python will fatally terminate trying to load a test
using importlib with an out of memory exception. Increasing RAM
allows reliable exection of all tests.
When logging is enabled TLS debugging is turned on which creates
a PEM file during runtime. There is no way for IWD itself to clean
this up since its meant to be there for debugging.
Newer QEMU version warn that msize is set too low and may result
in poor IO performance. The default is 8KiB which QEMU claims is
too low. Explicitly setting to 10KiB removes the warning:
qemu-system-x86_64: warning: 9p: degraded performance: a
reasonable high msize should be chosen on client/guest side
(chosen msize is <= 8192).
See https://wiki.qemu.org/Documentation/9psetup#msize for details.
We seem to be not specifying the msize for the root filesystem, which
results in this warning being printed:
emu-system-x86_64: warning: 9p: degraded performance: a reasonable high msize should be chosen on client/guest side (chosen msize is <= 8192). See https://wiki.qemu.org/Documentation/9psetup#msize for details.
There doesn't seem to be much performance difference in the end since
iwd does not process large files.
Right now the --valgrind option logs to a static file named
'valgrind.log'. This means that for any test that run multiple
instances of iwd, output is lost for all invocations except the last.
Fix that by using a per-process log file and making sure that all log
files are printed to stdout when the test ends.
This approach isn't perfect since it is possible for the pid to be
reused, but better than the current behavior.
test-runner will print out if files were left behind after a
test which lets the developer know something was not cleaned
up. But in this case test-runner should also remove these files
so they are not left, and printed, for each subsequent test.
Certain tests like testAP spawn two IWD process in separate
namespaces. When --valrind is used this eats up quite a bit
of RAM and causes the VM to run out of memory and start
killing off processes.
Since using --valgrind actually runs IWD using the valgrind
process the --verbose flag would only work if 'valgrind' was
also specified. This was taken into account with is_verbose
but the actual logic enabling stdout did not use that helper.
This was due, in part, to logging since is_verbose will always
return true if --log is used. To fix this a new flag was added
to is_verbose which omits the --log check to handle this
specific case.
There was a bug with process output where the last bit of data would
never make it into stdout or log files. This was due to the IO watch
being cleaned up when the process was killed and never allowing it
to finish writing any pending data.
Now the IO watch implementation has been moved out into its own
function (io_process) which is now used to write the final bits of
data out on process exit.
The processes in the list ultimately get removed for each
kill() call. This causes strange behavior since the list is
being iterated and each iteration is removing items. Instead
iterate over a new temporary list so the actual process list
can be cleaned up.
IWD_GENL_DEBUG is not generally useful anymore as it just prints a
hexdump of the raw data on the socket. The messages are quite verbose
and spam test-runner logs for little utility.
Process output was being duplicated when -v was used. This was
due to both stderr and stdout being appended to the write_fd list
as well as stderr being set to stdout in the Popen call.
To fix this only stdout should be appended to the write_fd list,
but then there comes a problem with closing the streams. stdout
cannot be closed, so instead it is special cased. A new
verbose boolean was added to Process which, if True, will
cause any output to be written to stdout explicitly.
The Namespace class was never being removed when tests finished.
This is fixed by unreffing the hwsim internal _radio object which
both cleans up the radio and allows the Namespace to be removed.
This moves all the de-init code into kill(), which fixes a few
reference issues causing processes to hang around longer than
desired. If the process terminates on its own and/or the last
reference is lost __del__ will kill the process and clean up.
There were a few issues with the cleanup of Hostapd. First the
process was only being killed, which did not actually remove
the process from the list.
In addition, with EAP-SIM/AKA tests, hostapd created sim_db
unix socket files which it does not clean up.
This is somewhat of an open issue/TODO but for now this avoids
the exception caused by trying to remove a radio that has been
moved to a namespace. Once a radio is moved hwsim loses that phy
and can no longer interact with it. This causes the Destroy()
method call to fail.
A cleanup parameter was added to __init__ which can be used
by processes which create any additional files or require more
a custom cleanup routine. Some additional house keeping was
done to make Process cleanup more robust.
Though multi-test processes seemed like a good idea in terms of
efficiency, the additional code/special cases was not worth it
for the only two multi-test processes (dbus/haveged). Intead this
concept was removed completely and TestContext/Namespaces will
now start all processes for each individual test. This also is
fair to all tests as a previous failed test could end up bleeding
into future tests.
Printing out processes was done manually but instead we can
make Process printing extendable by adding its own __str__
method. This now will print if the process is a multi-test
process as well.
Output files in namespaces were not handled differently and would
end up overwriting/duplicating files from the root namespace. These
are now named /tmp/<process>-<namespace>-out.
The process class was quite hard to understand, and somewhat
fragile when multiple output options were needed like verbose
and logging, and in some cases even an additional output file.
To make things simpler we can have all processes output to a
temporary file (/tmp/<name>-out) and set a GLib IO watch on
that file. When the IO watch callback fires any additional
files (stdout, log files, output files) can be written to.
For wait=True processes we do not use an IO watch, but do
the same thing once the process exits, write to any additional
output files using the process output we already have.
The log dir was never being cleaned out prior to a new logging
test run. This could leave old stale files around. Note that this
will remove any past log files so if you need them, you want to
make a copy before running test-runner with --log again.
Dbus should be started as a multi-test process from the
TestContext, which leaves the dbus address file around for
the full test run. For Namespaces dbus-daemon should be
closed when the Namespace closes.
