Hot on the heels of my last blog, let's pick up where we left off...
Stepping Through Drush
We’re now ready to activate CLI debugging in PHPStorm. Let’s test our debugger on Drush. Under “Run > Edit Configurations”, click “+” and create a new PHP Script.
- Under “File:”, select our project’s vendor/bin/drush command.
- Under “Arguments:”, we will pass “status” to test the drush statuscommand.
- Under “Custom working directory:”, select “sites/default” to run Drush on the default site (use a different site path if applicable).
To start debugging, select “Run > Debug…” and pick our Drush status script.
Success! PHPStorm opens and halts Drush at the first line.
If everything went well, the Drush script should open at its first instruction. Try out the “step over”, “step into” and “step out” debugging commands if this is your first time using a live debugger. When you’re ready, resume the script execution (the green triangle icon) to let the Drush command terminate. You should see the result of the Drush status command in the CLI console.
Now that we know our remote debugger is active, let’s attempt to debug the failing migration from above.
The Art and Science of Debugging
Our story resumes where I created a new script, with the same configuration as the Drush status script, except passing in “migrate-import mymigration_movies” as the command. I started a debug session, it correctly halted at the beginning of the vendor/bin/drush script. I resumed the code’s execution and got the correct status message from the migration. Then things got weird.
It’s worth pausing here to wax philosophical about debugging. I enjoy debugging. In software development, debugging is the closest we get to applying the scientific method of inquiry. A usual debugging session goes through this “scientific loop”:
- Observe some surprising, unknown and undesirable feature of our software (the bug),
- Formulate a hypothesis (or wild guess) about its cause,
- Verify the hypothesis by setting up a test that will reveal we were correct about the cause, but actually probably going to
- Fail again, in which case we should continue observing until a new hypothesis reveals itself.
An interactive debugger is like a programmer’s microscope — it lets the programmer focus on the code at the smallest possible resolution in time and scope, zooming around at will, instead of crudely dumping data to logs or the screen.
Based on the scientific loop, I was in the first stage, knowing with certainty what was failing in the system (the taxonomy term reference field’s save hook) but with no clue as to why things happened that way. Although the error message was giving me the exact line where the code was throwing an exception, putting a breakpoint on that line was likely to send me through hundreds of calls that were perfectly okay. What I wanted to do was observe the context of the system at the point of failure, and I could do that by setting a breakpoint on the exception.
- Under “Run > View Breakpoints”, click “+” and add a PHP breakpoint for the class Drupal\Core\Database\DatabaseExceptionWrapper.
With my fancy exception breakpoint active, I ran debug on my migration script, it halted at the first line of drush, and, confident I would soon be seeing the cause of my problem, I hit the run button to let it catch the first exception.
Then, nothing. The script ran to the end, I saw the exceptions appear in the PHPStorm console just as if I was running them straight through the terminal. Weird.
Maybe I used the wrong class name (new hypothesis). Let’s try catching all the exceptions.
Same result, script starts, halts at the first line, I resume and it runs to the end. Weirdly weird.
At this stage I had run out of guesses about what was taking place, so decided to revert to the observation stage of the scientific loop. I knew that my code was bootstrapping the migrate Drush commands, and those were located in the migrate tools module. Perfect place to insert some breakpoints and have a look around, I thought.
Still nothing! At this point, I realize that I am now debugging my debugging environment, which means it is time to go back to the beginning of the beginning, observing what is happening in the system.
The system is halting on the first line of the Drush script, that part is working. I decide to step through that script, line-by-line, to find out how exactly the migrate code gets loaded up.
The Drush code loads vendor/drush/drush/includes/startup.inc. All normal so far. I want to find out, out of the hundreds of lines in drush_startup(), which one specifically triggers the migration. Here we can take two approaches: use “step over” again and again until we see our output appear, or use a kind of divide-and-conquer-binary-search approach, using “run to cursor” over the middle of the function and starting the script over if our output has appeared. I opt to step over the code.
I find out the migration executes during a call to a PHP-level “process control extension” named pcntl_exec(). I’ve never heard of this, so I look up its documentation:
- pcntl_exec — Executes specified program in current process space
Hmm, let’s have a look at the arguments with another debugger pass. This time I use ‘run to cursor’ to go straight to the line, and print its arguments in the interactive console.
Wait a minute, this is calling a whole different script! I suddenly formulate a new hypothesis: I am running the wrong Drush script, and Xdebug isn’t going down the process chain. Let’s simply switch the vendor/bin/drush path in the PHPStorm debug script with vendor/drush/drush/drush.php and see if that’s the case…
My breakpoint in drush_migrate_tools_migrate_import() activates. And then the database exception. 😐
Back on track
There is no time to feel embarrassed about my misuse of command-line scripts for debugging, I can now do the actual task I set out to do: find out what is happening in my migration that causes it to insert raw values in the database.
Looking down the stack frames, there are about two dozen ordinary-looking entity storage methods being called before we hit something of interest: MigrateExecutable.php:224. This calls migrate’s EntityContentBase->import() method, which passes control to its own ->save() method, which builds an entity and saves it with the raw strings as values for the entity reference field. Clearly they are not meant to be raw strings, but adding breakpoints down the taxonomy module path, looking around, and then doing the same on the migration source processing path shows that everything is doing precisely what it is meant to do.
- Another hypothesis invalidated: the entity reference field setting “create referenced entities if they don’t already exist” does not magically convert tag names in migrations.
- New hypothesis: I am missing a part of the migration for transforming raw tag values into entity references.
That only takes a quick Google search to find out: the plugin is called entity_generate and is still an undocumented member of the migrate_plus contrib package. I add the plugin to the field_genre process plugin list, reimport my configurations, and run the debug script again.
Success! And more!
I open a glorious movie node and click a tag, enjoying the resulting genre listing with enormous satisfaction.
As a positive side-effect of stepping through the import process, I also discovered that my actor reference fields were turning up as empty arrays, though inspecting the neighboring variables quickly showed there was a typo in the migration name I had passed to the plugin, and it was failing silently. Please support this Drupal issue recommending an exception be created for such cases, making it easier to debug, if you agree.
The following links were useful in the process of solving this puzzle.
Drupal 8 Migration: Migrating Taxonomy Term References (Part 2) from evolvingweb.ca,
A script to turn on Xdebug within a terminal session instead of going through PHPStorm,
Debugging Drush Commands with Xdebug and PHPStorm from lullabot.com,
Debugging Your Migrations in Drupal 8 from imagexmedia.com.
This blog post was originally posted on Appnovation's website on August 9, 2017 by Mathieu Hélie.