How do I print debug messages from a script?

The Log module provides you with functionality to log and display arbitrary (small) text messages during script execution. This is useful while debugging a load script, but also if you want to e.g. verify content that is returned from a server and get an alert if some content is not what you expected. All log messages are displayed on the log tab of the test result page. Of course, if you use the “validate” functionality to validate a user scenario, you never visit the test result page and in that case your log messages will be displayed in the right part of the editor window instead. It's generally a best practice to limit logging during a test.  If you are keeping track of something of interest, i.e. a failed response. It is better to create a custom metric.

There are several log functions that perform the same, basic action (log text) but that formats the text slightly differently. You have:

log.info() Standard log function. Causes text to be displayed at the bottom of the test result page for the test that was executed
log.debug() This does the same as the log.info() function, but the text will be displayed with a slightly different background color, to make it stand out from regular log.info() messages
log.error() This logs text with a red background, to make it really stand out from other text. Only use this to log situations you consider an error.

Example:

-- Make an HTTP request and verify returned content. If it is not what we expect
-- we log an error using the log.error() function
local request = http.request({"GET",     "http://test.loadimpact.com/pi.php?decimals=18",
    response_body_bytes=100  -- Tell the system it should store up to 100 bytes of body data for us
})
if request.body ~= "3.141592653589793238" then
    log.error(
      "PI calculator returned unexpected result when stressed with "
         .. test.get_clients() .. " simulated clients: " .. request.body
    )
end

 

Limitations

In order to prevent excessive logging by a malfunctioning or badly programmed script, we limit the number of messages that can be logged in any given 3-second reporting time period (see - What result metrics are reported for a URL? for more info about how reporting data is stored and transferred) to 100 messages. This means that if your script logs 1000 messages within 3 seconds, chances are you will only see the first 100 of those messages. The rest will be quietly discarded by the load generator application.

It's also important to note that you must set response_body_bytes when capturing the response.  Failure to set this will result in an empty response body.  In the example above, we set the response body to 100 bytes.  The full response body or the limit up to the number of bytes captured is available. That is, you can run a string.match on the entire response even though we only will display 1024 bytes in the log window(explained below).

Each log message can also be max 1024 bytes (characters) in length before it is truncated. I.e. if you try to log a text message that is 1100 bytes long, the actual text that is logged will only be the first 1024 bytes of your message, the remaining 76 bytes will be lost.

If you know the data you are looking for you can workaround this limit by conducting a string search.  Once you find the position of the data, you can then avoid logging the output before that point. Here is an example of a string search:

local s = response[1].body
local position = string.find(s, "csrf-token")
if position == nil then
log.info("Failed to find string: csrf-token")
else
log.info(string.sub(s, position))
end

Earlier, (before May 2012) logging worked in a different way – we used fixed-size, rotating buffers to store log messages, which meant that in case you logged too many messages in a 3-second reporting period, the first messages would be lost, not the last ones. Also, log messages were not transferred to, and stored in, the results database immediately. They were collected by the load generator application in these rotating buffers instead. Then, at the end of every 3-second interval the rotating buffers were flushed and all logged messages were sent to the results database to be stored (meaning they can then be seen by the user in the test result output). The problem with this approach was that if you e.g. used the logging functionality to debug runtime problems in your load script – for example printing out the value of a variable just before the script crashes – there was a very big chance you would never see the log output as the next line of code will usually be executed within milliseconds of your logging statement being executed, meaning your logged message never gets the chance to be sent to the results database.

 

Feedback and Knowledge Base