WARP Project Forums - Wireless Open-Access Research Platform

There won't be a valid entry header since it's part way through reading the log...

Correct - this is the source of the error you're seeing.

The logging code at the node maintains minimal state. The application requests space for a log entry of a given size. The logging framework returns a pointer to a DRAM location, then advances its internal pointer by the requested size. The logging code does not maintain an index of already-written entries - it does not know where previous entries start/stop.

When wlan_exp reads log data it specifies the range of bytes it needs. The node's log code returns those bytes. This handshake treats the entire log memory section as a binary blob. Neither environment operates on log entry boundaries when transferring log data over-the-wire.

Further, the node does not maintain state about what log data has been read by a given wlan_exp master. This was a conscious design choice, enabling multiple Python masters to retrieve the same log data without any extra bookkeeping at the node. node.log_get_all_new() uses a property in the wlan_exp node object to record the ranges of log data which have already been retrieved. Multiple calls to log_get_all_new() are safe as long as the wlan_exp node object and the actual node are not reset.

The gen_raw_log_index() utility requires a log data byte array that starts at the first byte of a log entry. It uses only the log entry headers to build its index and to jump ahead to each log entry. The gen_raw_log_index() code does not parse each entry's contents. Again this was intentional - you can run gen_raw_log_index() for arbitrary log data arrays without knowledge of each log entry's format.

All together, this means you should run log_get_all_new() as many times as you need to gather raw log data, then run gen_raw_log_index() at the end of the retrieval. If your experiment requires parsing log data while the node is still writing log entries, you should be able to run gen_raw_log_index() multiple times, always referencing the entire log data array.

Hi, thanks for your responses on this, they cleared up some confusion. I think my solution covers both your answers.
Initially I was trying to gather log data, then run gen_raw_log_index(), then gather more log data and store this in a new location (i.e Not append it to the first set of log data) then run gen_raw_log_index() again. gen_raw_log_index() failed the second time since the log data was missing the first section of the log, does this sound correct?
I have fixed this by changing my script to use node.reset(log=True) in between consecutive reads of the log, which is fine for my application.
Must log data always be written to a hdf5 container (as per log_capture_continuous) or can it simply be stored as a python variable, bytearry or similar?

Initially I was trying to gather log data, then run gen_raw_log_index(), then gather more log data and store this in a new location (i.e Not append it to the first set of log data) then run gen_raw_log_index() again. gen_raw_log_index() failed the second time since the log data was missing the first section of the log, does this sound correct?

Yes, this is the expected behavior, since gen_raw_log_index() requires an input byte array that starts at the first byte of a log entry.

Must log data always be written to a hdf5 container (as per log_capture_continuous) or can it simply be stored as a python variable, bytearry or similar?

Using hdf5 files is not required. The examples use hdf5 for easy storage of raw and processed log data, demonstrating how the log capture and log analysis steps can be safely separated, even run on different machines.

Can we roll a log file without writing the log index to it - so each roll is simply a blob of contiguous data. Then when parsing, combine all rolls in memory one after the other, then use .write_log_index() to write the index of the whole thing (lots of memory required)?

I think this is a good approach. The wlan_exp HDF5LogContainer class provides a thin wrapper over raw HDF5 files, and the h5py package provides a numpy-compatible interface to HDF5 containers. Re-assembling a group of log data segments from individual HDF5 files into a valid log data file is pretty easy.

Here's a quick proof-of-concept:

Script #1: create multiple HDF5 files each containing 4MB of log data. This script starts from a valid log file and creates 11 new HDF5 files. Your actual experiment would replace this with a script that repatedly reads data from a node and writes a new file. The important point here is that the segment files are not valid "log file" - they are just HDF5 contrainers for a 4MB binary blob.

import numpy as np

import wlan_exp.log.util as log_util
import wlan_exp.log.util_hdf as hdf_util

LOGFILE_ORIG = 'ap_two_node_two_flow_capture.hdf5'
SEG_SIZE = 4 * 2**20 #4MB

# Open the original file
h5_file_orig = hdf_util.hdf5_open_file(LOGFILE_ORIG, readonly=True)

# Access the HDF5 dataset named 'log_data'
log_data_ds = h5_file_orig['log_data']
log_data_len = len(log_data_ds)

# Iterate over the log data, writing one new HDF5 file per segment 
idx = 0
seg_index = 0
while seg_index <= log_data_len:
    if (seg_index + SEG_SIZE) < log_data_len:
        # Write full segment to new HDF5 file
        d = log_data_ds[seg_index : seg_index + SEG_SIZE]
    else:
        # Write final partial segment
        d = log_data_ds[seg_index : log_data_len]

    # Create empty HDF5 file
    h5_file_seg = hdf_util.hdf5_open_file('log_data_seg_{0:02}.hdf5'.format(idx))

    # Create and write the 'log_data_seg' dataset
    h5_file_seg['log_data_seg'] = d
    h5_file_seg.flush()
    h5_file_seg.close()

    idx +=1
    seg_index += SEG_SIZE

Script #2: create a new empty log data file, read the 11 partial log data files, appending each segment to the output log file

import numpy as np

import wlan_exp.log.util as log_util
import wlan_exp.log.util_hdf as hdf_util

LOGFILE_OUT = 'log_data_stitched.hdf5'
SEG_FILES = sorted(['log_data_seg_{0:02}.hdf5'.format(i) for i in range(0,11)])

# Create the new empty log file using the HDF5LogContainer wrapper
h5_file = hdf_util.hdf5_open_file(LOGFILE_OUT, readonly=False)
log_file_out = hdf_util.HDF5LogContainer(h5_file)

for f in SEG_FILES:
    # Open the segment file
    h5_file_seg = hdf_util.hdf5_open_file(f, readonly=True)

    # Access the 'log_data_seg' dataset
    d = h5_file_seg['log_data_seg']
    log_file_out.write_log_data(d[:])

# Write a log data index to the new log data file
log_file_out.write_log_index()

I quickly tested this with one of our sample data files, successfully comparing the output of log_process_summary.py for the original and re-assembled file.

Details on crash: This morning one had crashed overnight, resulting in the Python error "Did not provide any log data". I didn't have UART plugged in but doing so now, CPU LOW reports: "Stuck waiting for MAC_HW_LASTBYTE_ADDR1: wlan_mac_get_last_byte_index() = 0". Repeatedly printed to UART.
I will rerun with UART attached but with three nodes it's tricky to know which one will fall over and when. Typically in my environment the node on channel 1 dies first, but this time it was channel 6.

Another hung state when using NOMAC (previous post was using DCF MAC): "Stuck in wlan_mac_hw_rx_finish! 0x00008180"

Another hung state when using NOMAC (previous post was using DCF MAC): "Stuck in wlan_mac_hw_rx_finish! 0x00008180"

Details on crash: This morning one had crashed overnight, resulting in the Python error "Did not provide any log data". I didn't have UART plugged in but doing so now, CPU LOW reports: "Stuck waiting for MAC_HW_LASTBYTE_ADDR1: wlan_mac_get_last_byte_index() = 0". Repeatedly printed to UART.

Thanks for these details. Are you running the stock v1.5.3 design? If not can you describe any customizations you've made to the code/cores?

First, apologies for the crashes. I really thought we had squashed the last bug in MAC/PHY Rx state that manifests like this.

You mention channels 1,6 above. Do you only see this behavior when tuned to 2.4GHz channels? One debug step would be to disable the DSSS receiver logic ("n.enable_dsss(False)" in Python). Unfortunately the "stuck" prints above don't include the status bit that encodes which PHY (DSSS vs OFDM) is holding the RX_PHY_ACTIVE bit.

Disabling DSSS appears to make no difference. It still hangs, most often with the 8180 error. Any more thoughts on this? Can I add some extra debug lines for you?

Thanks for the 'in memory' Python script for concatenating logs. This works well. However I needed to use np.dtype('u1') rather than np.dtype('V1'). I don't see it should make a difference but numpy complains otherwise. Also added h5_file_seg.close() in the loop.

Hello, thanks for this. Here is the status bits from a recent crash. Not one we've seen before: 20100.

Stuck in wlan_mac_hw_rx_finish! 0x00020100
MAC HW Status: 0x00020100
Rx Hdr Params: 0x0A050085
Rx PHY Status: 0x00000002

Stuck in wlan_mac_hw_rx_finish! 0x00020100
MAC HW Status: 0x00028100
Rx Hdr Params: 0x0A050085
Rx PHY Status: 0x00000002

Stuck in wlan_mac_hw_rx_finish! 0x00020100
MAC HW Status: 0x00020100
Rx Hdr Params: 0x0A050085
Rx PHY Status: 0x00000002

Three repetitions are listed to highlight the *occasional* difference in wlan_mac_get_status() of 0x00028100 vs. 0x00020100. The 28 version appears every ~100 iterations. Clearly one bit changes between the 'Stuck in...' printf and the 'MAC HW ...' printf. I guess it's toggling and the printf sometimes catches it?

Thanks for the RX PHY reset code.

Versions are:
Spyder: 2.3.0rc
Python: 3.4.1 (64bit)
Numpy: 1.8.1

I have rerun this experiment using only log_capture_continuous.py to capture a log which should wrap and observe the same problem. When the script ends it calls gen_raw_log_index() to write the index to the hdf5 file.

For captures which have wrapped in the log, it gives an Exception.  ERROR: Log file didn't start with valid entry header (offset 1048018024)!

As above there are no modifications to either the node, python wlan_exp framework or the capture scripts; A clean v1.5.3. Is this usual behaviour?

I'm trying to reproduce any issues with log wrapping in v1.5.3, so far unsuccessfully.

I'm running an AP+NoMAC node with stock v1.5.3 C and wlan_exp.

For quicker testing you can modify EVENT_LOG_SIZE in wlan_mac_high.h (i.e. "#define EVENT_LOG_SIZE (100 << 20)"). I tested both with and without this change.

I then modified log_capture_continuous.py as follows:

import import wlan_exp.ltg as ltg

LOG_READ_TIME = 5
MAX_LOG_SIZE = 1.1e9 #Stop shortly after log wraps

def run_experiment():
    ...

    # Add the current time to all the nodes
    wlan_exp_util.broadcast_cmd_write_time_to_logs(network_config)

    # Log testing - log full payloads, generate backlogged multicast flow with long payloads, short Tx time
    node.reset(log=True)
    node.log_configure(log_wrap_enable=True)
    node.set_tx_rate_multicast_data(mcs=7, phy_mode='NONHT')
    node.log_configure(log_full_payloads=True)
    node.configure_bss(ssid="AP-Test", channel=6, beacon_interval=None)
    node.ltg_configure(ltg.FlowConfigCBR(dest_addr=0xFFFFFFFFFFFF, payload_length=1400, interval=0), auto_start=True)

   ...

I also found that the default log_capture_continuous requires that I hit enter after the nominal ending condition to actually terminate the script. I think this is due to raw_input() blocking. This script was originally tested in ipython, maybe it behaves differently there. For easier testing I just deleted this code from the script:

### Removing this code so script can self-terminate with no keyboard input ###

        # See if there is any input from the user
        while not input_done:
            sys.stdout.flush()
            temp = raw_input("")

            if temp is not '':
                user_input = temp.strip()
                user_input = user_input.upper()

                if ((user_input == 'Q') or (user_input == 'QUIT') or (user_input == 'EXIT')):
                    input_done = True
                    exp_done   = True

### END: Removing this code so script can self-terminate ###

This logging+LTG setup will generate ~10MB of log data per second. In my setup this script runs for a while then writes a ~1.1GB log file and generates a valid index for the file.

A few observations:
-The node.get_log_size() method returns two values:
   -Log capacity: the number of bytes reserved in DRAM for log data data memory (1048018944 bytes in the v1.5.3 reference code)
   -Log size: the number of bytes of valid log data currently contained in the log data memory.

The log size is always <= the capacity. It will be less than the capacity when the last log entry leaves too few bytes at the tail of the memory block to write another entry; the logging code will not wrap a partial entry. Given this definition, the reported log size does not change after the log wraps, because the log memory area still contains that many bytes of log data and pre-wrap log data can still be retrieved before it is overwritten.

The values returned by node.get_log_indexes() have more information, including the number of times the node's log has wrapped.

-The node.log_get() method prints a spurious warning when reading log data from the end of the log data memory block: "WARNING:  Trying to get 4294967295 bytes...". This occurs because log_get_all_new() uses 0xFFFFFFFF as a magic value to ask the node to return all valid data from "offset" to the end of the log memory array. I just committed the fix.