Friday, January 1, 2021

Cypress How-To: different logging mechanisms for debugging.

Introduction

As I wrote earlier in a blogpost now we have the cypress.io test framework integrated into Collabora Online codebase. We use this test framework to run automatic tests against the code base as part of the CI process. When a test fails it's crucial to have proper logging to make it easier to find out, why a test fails. Also, we need a way to add additional logging messages for debugging a test case in detail. In this post, I'll try to summarize the different loggings available for cypress tests.

Cypress log

Cypress itself has a logging capability, which is used to record the steps made by a test case. For all commands that a cypress test runs, we will have a line in the cypress log. This log is the first thing we can see in case of a test failure. From this log, we can find out at which step the test failure occurred. This log is displayed, in one hand, in the command line (see below), but it also saved under cypress_test/cypress/logs folder:

The cypress command log above shows, on one hand, the cause of the failure: Expected to find element: `#fontnamecomboboxs`, but never found it.. It seems we don't have the DOM element with the ID of fontnamecomboboxs. The log also shows that at which step we get that failure. In this specific test case we do the following steps before the failure: 1) load the test document, 2) switch to editing mode (mobile), 3) select all text in the document, 4) open the mobile wizard. After the fourth step we try to push an item on the mobile wizard, that is missing, so the test fails.

By default, this cypress log contains logging for cypress commands. However, we can add additional logging to the test code. We can use cy.log() method for that. Anything we print out with this method will be shown in the cypress log. For example, we use this logging function in helper methods to display the beginning and the end of the method, so it's easier to understand the log. See openMobileWizard() method for example:

It is diplayed in cypress log like this:

loolwsd log

We also save the loolwsd log during a test run. In this log, we can find information about the messages sent between the client and the server. It's the same log file, what we have for the actual Collabora Online under the /tmp/ folder with the name loolwsd.log. In case of cypress tests, we put this log file under /cypress_test/workdir folder. This file always contains the log of the last test run. This "last run" can mean all the tests (e.g. make check), can be only one test suite (make check-mobile spec=writer/apply_font_spec.js) or even only one test. It depends on the command we last run. This log is very verbose, so in most cases, it's best to filter for specific messages to get useful information from it. An example loolwsd.log is shown below:

To add additional debugging information to this log you can use the LOG_DBG(), LOG_TRC(), LOG_INF() methods.

loolwsd's command line output

Besides these logs, we also record the command line output of the running loolwsd server. It's the same output that we get for top-level make run command. This output first displays the details related to the started loolwsd (e.g. browser links for hello word files or admin console). On the other hand, the same output can be used to debug LO core code behind Collabora Online. We can use SAL_DEBUG() to write out anything to this output, called from core code and also crash traces are printed here. This output file can be found at cypress_test/workdir/loolwsd_ouput.log. This output looks like the below example: