Allow logging for non-strings values

I suggest that you take advantage of the __toString() method that an object might have.

According to the comments here https://www.php.net/manual/en/function.is-string.php#121637 the is_string() will return FALSE even if there's a __toString()

I'm proposing a small improvement.

Nice idea and tests updated, great.

This can be simplified with var_export($value, TRUE). For examples, see the Concat and Explode process plugins in the migrate module.

Fixed php and code sniffer errors. Use var_export inside of printr().

Seems like a good idea to me.

Changed the name of the data provider to not begin with 'test'. Added a simple test with an object. Added some docs.

1. +++ b/core/modules/migrate/src/Plugin/migrate/process/Log.php
   @@ -31,6 +31,11 @@ class Log extends ProcessPluginBase {
   +      $value = var_export($value, TRUE);
   

   This would rather break the plugin's purpose (and almost all migrations using it) as it's currently implemented. The purpose of this plugin is to take an input value, log it, and then pass it through unchanged. Now the patch is changing it, and returning the changed (exported string) value. So any chain of process plugins that use non string values that have the log plugin injected somewhere in the middle would break.

2. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -20,17 +20,64 @@ class LogTest extends KernelTestBase {
   +    $saved_message = $plugin->transform($log_data, $executable, $row, 'buffalo');
   +    $this->assertSame($expected_message, $saved_message);
   

   The plugin docs state:

   /**
    * Logs values without changing them.
    *
   

   Yet the new test specifically tests that the values are being changed.

   At a minimum, the plugin need to log the exported value, but still return the original value

Additionally:

1. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -20,17 +20,64 @@ class LogTest extends KernelTestBase {
   +  public function logTestProvider() {
   

   For kicks and giggles, can we add scenarios for a Url, Node and FormattableMarkup?

2. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -20,17 +20,64 @@ class LogTest extends KernelTestBase {
   +        'Testing the log message',
   +        'Testing the log message',
   

   Here and below, can you we add array keys that correspond with the variable names passed into testLog? Which would maybe make us want to rename the variables. I like $actual_message and $expected_message.

#9 and #10 contain sufficiently clear instructions for a novice to take this on I think :)

Adding DrupalSouth 2019 tag

I am working on this as part of the DrupalSouth 2019 contribution day.

Hi,

The attached patch includes suggestions from #9 and #10. One thing to note is that, if the `log` plugin returns the value verbatim, the test might not be accomplishing its intended purpose. As of now, the test checks if the returned value is the same as the one sent to the plugin. But I think the intent of test is checking for the *logged* value, which is different from the *returned* value. Would we have to actually read the messages table?

@heddn, when you say add scenarios for Url, Node, and FormattableMarkup do you mean Drupal\Core\Render\Element\Url, Drupal\node\Entity\Node, and Drupal\Component\Render\FormattableMarkup? If so, could something like Drupal\Tests\migrate_drupal\Traits\CreateTestContentEntitiesTrait for creating the test node?

re #15:

Yes, the test needs to load the message results and review those.

The scenarios I was thinking of was just objects. These objects (looking at node) do no need to be saved objects.

For Url, I was thinking Drupal\Core\Url. The reason I proposed these, is it 1) tests things that are commonly logged and 2) shows how the logger can be used.

As of now, the test checks if the returned value is the same as the one sent to the plugin. But I think the intent of test is checking for the *logged* value, which is different from the *returned* value.

Yes, the test needs to load the message results and review those.

To be clear, the test should ALSO STILL test to make sure the returned value is unchanged, so we don't inadvertently commit something like #2 in the future.

Thanks dinarcon.

This has fixes for #16 and #17. The log plugin fails on the var_export when the input value is a Node object. A problem I haven't looked into yet. know a way around that?

Some much needed cleanup ( I am finding it a challenge to work on broken screen).

Unfortunatelly I spent some time, but I didn't find how to solve this problem:
The log plugin fails on the var_export when the input value is a Node object. A problem I haven't looked into yet. know a way around that?
Maybe we can use serialize or json_encode instead var_export?

If the object implements EntityInterface, then it should call toArray() before it var_dumps().

Ah, that is what I was looking for, Should be all fixed now.

Maybe try adding a try/catch \Throwable for the var_export in case things go south with other objects?

Hi All, I have the addedtry and catch blocks for var_export. Please review my patch.

Reviewed the patch and tests, seems okay for me!

Just fixing a coding standard error.

Thanks @quietone for the minute observation, It follows the

Drupal.WhiteSpace.ScopeClosingBrace

rule.
+1 RTBC

+++ b/core/modules/migrate/src/Plugin/migrate/process/Log.php
@@ -31,8 +32,24 @@ class Log extends ProcessPluginBase {
+      try {
+        $message = var_export($export, TRUE);
+        $migrate_executable->saveMessage($message);
+      }
+      catch (\Exception $e) {
+        $migrate_executable->saveMessage($e->getMessage());
+      }

Why the try catch here? Looking at the docs on I can't see when one would be thrown - https://www.php.net/manual/en/function.var-export.php.

I think this can be written with less logic as:

  public function transform($value, MigrateExecutableInterface $migrate_executable, Row $row, $destination_property) {
    $export = $value;
    // Transform the value before logging if not a string.
    if (!(is_string($export) || (is_object($export) && method_exists($export, '__toString')))) {
      if ($value instanceof EntityInterface) {
        $export = $value->toArray();
      }
      $export = var_export($export, TRUE);
    }
    // Log the value.
    $migrate_executable->saveMessage($export);

    // Pass through the same value we received.
    return $value;
  }

The try/catch was suggested by heddn in #25.

This patch makes the changes suggested in #34. The only question that remains is about the try/catch.

Well did the try catch actually catch the error eluded to in #22?

I don't recall all the details from #22. But catching throwable (instead of exception) will also catch errors/warnings. I seem to recall that would be helpful in the case of what was fixed in #26.

#34. Reworked the flow of the patch.
#36. the error referred to in #22 is resolved by converting the input to an array ($value->toArray()) before using it in the var_export.
#37. This patch changes the catch to a catching a throwable.

I'm setting this back to NW. Trapping errors like that is a bad code smell to me. First, I'm not sure how a node could ever end up as an input to a process plugin, but I'll give that it's technically possible in custom code. Second, I don't see that var_export triggers any errors according to the documentation, so the fact that we are trying to trap one seems off.

I would rather test for and export things we can, and log the fact that we have an unloggable value passed for things we can't. My biggest concern would be SimpleXmlElements and such from the contrib xml source.

OK. New version that will log anything that is not an object and cleanup the process plugin. Also, added a test for boolean and updated the patch to 9.1.x.

The only test is failing because a value isn't truncated to x digits.

Drupal\Tests\migrate\Kernel\Plugin\LogTest::testLoggable with data set "float" (1.1229999999999999982236431605997495353221893310546875, ''buffalo' value is '1.123'')
Failed asserting that two strings are identical.
--- Expected
+++ Actual
@@ @@
-''buffalo' value is '1.123''
+''buffalo' value is '1.1229999999999999982236431605997495353221893310546875''

Yes, fun having different test environments. That works just fine locally.

Added an sprintf for the float instead of using var_export. Then reworked the logic of the process plugin

Closer, but we can handle more stuff than this. Things that are strings or numeric should be able to to be directly logged. Objects implementing __toString should have their strings logged, arrays should be print_r'd etc. SimpleXmlElements should be tested for, becasue migrate_plus can provide them. we can't really log them, but we should test that we output something along the lines of "logging attempted for an xml object, but that is not serializable" or something along those lines.

This is going round in circles.

Do we want to use var_export or print_r? SimpleXmlElements has a __toString method so why not log it?

I wanted to improve the test so here is another version.

1. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -16,21 +19,168 @@ class LogTest extends KernelTestBase {
   -  protected static $modules = ['migrate'];
   +  public static $modules = ['node', 'migrate'];
   

   protected

2. It'd be great if @mikelutz could +1 this and say that everything has been addressed from #47.

3. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -16,21 +19,168 @@ class LogTest extends KernelTestBase {
   +      'url' => [
   +        'value' => $url,
   +        'expected_message' => "Unable to the log the value for 'foo'",
   +      ],
   

   The URL object implements toString() not __toString() cause reasons. I think given how common URL objects are it might be worth detecting toString() and calling it.

4. +++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
   @@ -16,21 +19,168 @@ class LogTest extends KernelTestBase {
   +    foreach ($data as $datum) {
   +      // Test the input value is not altered.
   

   This test might be better implemented as a data provider.

1 Fixed
2. I agree
3. Fixed
4. This did have a dataprovider but that doesn't allow for the creation of Nodes (the data provider runs before setup) so there had to be two test methods and I didn't see the point of multiple methods.

+++ b/core/modules/migrate/src/Plugin/migrate/process/Log.php
@@ -31,9 +32,27 @@ class Log extends ProcessPluginBase {
+      method_exists($value, '__toString') || method_exists($value, 'toString')) {
+      $export = print_r($value, TRUE);

Unfortunately this won't work. We'll need to call toString() ourselves because PHP won't call it automatically. It's not magic.

+++ b/core/modules/migrate/tests/src/Kernel/Plugin/LogTest.php
@@ -16,21 +18,168 @@ class LogTest extends KernelTestBase {
+        'expected_message' => "'foo' value is '" . print_r($url, TRUE) . "'",

here we should have the url hardcoded because it makes the test easier to read.

I am setting the status to NW for #51 and #52.

@alexpott, thanks for the reviews.

This changes the url creation and test.

My wife happens to be watching The Princess Bride right now, so I have to paraphrase a famous line:

I do not think that code means what you think it means.

I am referring to these lines (after applying the patch):

    else {
      if ($value instanceof EntityInterface) {
        $export = print_r($value->toArray(), TRUE);
      }
    }

    $message = $export ? "'$destination_property' value is '$export'" : "Unable to the log the value for '$destination_property'";

This is why PHP has a bad reputation:

Psy Shell v0.10.4 (PHP 7.3.20 — cli) by Justin Hileman
>>> echo '' ? 'foo' : 'bar';
bar⏎
>>> echo '0' ? 'foo' : 'bar';
bar⏎
>>> echo 0 ? 'foo' : 'bar';
bar⏎
>>> echo 0.0 ? 'foo' : 'bar';
bar⏎
>>> echo '0.0' ? 'foo' : 'bar';
foo⏎

Since earlier lines of code pass integers and floats through sprintf() or print_r(), only my first two examples are relevant: if the value is 0 (integer) or '' (string), then the message will be set to "Unable to the [sic] log the value ...".

I suggest

1. Turn the last else { if() {...} } into an elseif () {...}.
2. While you are at it, test for method_exists($value, 'toArray') instead of $value instanceof EntityInterface and remove the use statement.
3. Add else { $export = NULL; }.
4. Change the condition in the ternary expression to $export === NULL.
5. Break the ternary expression before ? and :. That is, add line breaks.
6. Remove the stray "the" from the I-give-up message.

If you do (2), then consider rearranging the conditions so that the toArray() test is next to the toString() test.

Finally, the Migrate Plus module has several process plugins that pass around DOMDocument objects. We could handle those by applying the saveHTML() or saveXML() method. Given the history of this issue, I will not object if you want to defer this suggestion to a follow-up issue.

My previous comment did not say anything about the tests.

1. I do not understand these changes:

    -use Drupal\migrate\MigrateExecutableInterface;
    +use Drupal\migrate\MigrateExecutable as CoreMigrateExecutable;
    ...
    +  /**
    +   * Migrate executable.
    +   *
    +   * @var \Drupal\migrate\MigrateExecutable
    +   */
    +  protected $executable;
    ...
    +    $this->executable = new MigrateExecutableTest($migration);
    +    $this->executable->sourceIdValues = $definition['source']['data_rows'][0];
    ...
    +/**
    + * MigrateExecutable test class.
    + */
    +class MigrateExecutableTest extends CoreMigrateExecutable {
    +
    +  /**
    +   * The configuration values of the source.
    +   *
    +   * @var array
    +   */
    +  public $sourceIdValues;
    +
    +}

   I am not sure if it is OK to have an @var comment for one class and then assign an object of a child class to the variable. I am sure that if we refer to the $sourceIdValues property, then $this->executable has to be a MigrateExecutableTest object. If our test class were called MigrateExecutable instead of MigrateExecutableTest, then we would need to use Drupal\migrate\MigrateExecutable as some other name … but we do not call it that.

2. Is it important that we test with an actual Node object? We could remove the dependency on the node module by adding a toArray() method to our other test class. Maybe add a saveHTML() method, too. And then we could rewrite the test to use a data provider, as discussed in #49.4 and #50.

3. Typo:

    +class ObjWithSting {

4. I would rather use explicit constant strings for the expected messages:

    +        'expected_message' => "'foo' value is '" . print_r(['key' => 'value'], TRUE) . "'",
    +        'expected_message' => "'foo' value is '" . print_r($node_array, TRUE) . "'",
    +        'expected_message' => "'foo' value is '" . print_r(new ObjWithSting(), TRUE) . "'",
    +        'expected_message' => "'foo' value is '" . print_r(new \SimpleXMLElement($xml_str), TRUE) . "'",

5. Can we add test coverage for the cases I mentioned in #55?

6. Should we clear the messages at the start of the loop instead of the end? If we convert to a data provider, do we need to do it at all?

7. The $idMapPlugin variable is a class property so that it can be set in setUp() and used in the test method. Why not just make it a local variable in the test method?

8. Sorry for putting the really big question at the end, but do we really need a kernel test instead of a proper unit test? If we create a mock MigrateExecutable class and a mock Row class, then we can test the transform() method without creating a migration for it.

This is a work in progress. The only changes are to LogTest.php.

55.1 Added tests for int 0 and empty string
55.final paragraph. Definitely agree to a follow up! Increasing logging ability is too important to wait for additions.

56.2 That was requested by heddn in #10 and it makes sense to me. See all the second paragraph of #15 and #16.
56.3 typo fixed
56.4 Painful but done.
56.5 Added the two cases mentioned in 55.1
56.6 I don't think it matters when they are cleared. Instead of clearing the message I changed the loop so that there are
unique source id values for each row and then get the messages for those source id values.
56.7 Because then $migration would need to be a class property too.
56.8 NP. It is a kernel test because Log does $migrate_executable->saveMessage($message) and I don't know how to make that work in a unit test.

@quietone:

Thanks for the updates. I will look at the updated patch later. For now, just a couple of follow-ups:

#56.7: Couldn't we replace $idMapPlugin (class property) with $id_map_plugin = $this->executable->getIdMapPlugin() (local variable)? I think the executable delegates that method to its Migration property.

#56.8: I think I like the idea of having a simple Kernel or Functional test to make sure that logging is functional. But I am afraid that this patch makes the test overly complicated.

In order to test the improved functionality from this issue in a unit test, we just have to pass various parameters to the public transform() method. The Row parameter is easy: $row = new Row();. So the hard part is the MigrateExecutableInterface object.

One option would be to create a TestMigrateExecutable class that could be used in various tests. For this test, would just need do-nothing implementations of import(), rollback(), and processRow(); and a simple implementation of saveMessage(). I would call that a mock executable, but maybe I should avoid that term.

The other option might not work; you are more familiar with the Prophecy framework than I am. Can we use it to create an object with a saveMessage() method that is good enough for this test?

This should fix all the points from #55, which were fixes to the log plugin.

#56.8 Unit test added, thanks to alexpott who explained to me how to test the log message. The Kernel test is still there for the Node and Url source values.

Still to do: #56.1, #56.7 (again). Note that I haven't had a chance to do a self review.

I had a quick look at the interdiff, and it looks very good.

Since we are replacing $value instanceof EntityInterface with method_exists($value, 'toArray'), I think we can get rid of the use statement.

Another increment.

#56.7 Fixed.

And fixed coding standards and checked spelling.

And finally fixes for #56.1. For that @var now refers to the correct test migrateexecutable which has a name change to TestMigrateExecutable, which is the same as in other tests that require a test migrateexecutable. I think it is easier to read as well.

And then I saw that the expected message was still using print_r (#56.4). The print_r is gone and so is the $url variable.

I expect this will be the last change I make until there is feedback.

Yeah, I think this covers everything. I'm glad we took the time to work through all the possible scenarios and write proper tests.

Re-running test

Failure in Drupal\Tests\ckeditor\FunctionalJavascript\CKEditorIntegrationTest. rerunning test.

Back to RTBC

1. +++ b/core/modules/migrate/tests/src/Unit/process/LogTest.php
   @@ -0,0 +1,111 @@
   +      ],
   +      'object_with_to_String' => [
   +        'value' => new ObjWithString(),
   +        'expected_message' => "'foo' value is 'Drupal\Tests\migrate\Unit\process\ObjWithString Object\n(\n)\n'",
   +      ],
   

   Shouldn't we be asserting the string 'a test string' here?

2. +++ b/core/modules/migrate/src/Plugin/migrate/process/Log.php
   @@ -31,9 +31,31 @@ class Log extends ProcessPluginBase {
   +      $export = print_r($value->toArray(), TRUE);
   +    }
   +    elseif (is_string($value) || is_numeric($value) || is_array($value) || method_exists($value, '__toString')) {
   +      $export = print_r($value, TRUE);
   +    }
   

   Which would mean we should be casting the object to string here instead of print_r the raw object with no cast.

I've made the change but then the XML output is just '\n\n'.

@esolitos, thanks.

That idea works for me so here is a patch with the above suggestion. Just made a small change so only the value of $value is inside the single quote.

I think the solution here is either to include also the object class in the message (see example below) so if a developer sees SimpleXML will understand that there might be more than meet the eye, or add a special handling of SimpleXML objects, but then how many more edge cases would we need to add?

I actually would support handing SimpleXMLElements as a special case because they are easy to create with the migrate_tools module, but I think the improvement in this patch is useful enough to commit as-is and I've created a follow up #3182296: Improve logging of SimpleXML elements in the Log process plugin. to see if we can better handle SimpleXMLElements. I really don't want to hold this up any more and would prefer to iterate on it later if there is a need. This patch more than covers the 80% use case threshold that I look for in improving current systems.

@mikelutz, thank you! I agree get these useful changes in asap and then work on improvements.

Committed fad126b and pushed to 9.2.x. Thanks!

This broke PHP 8 testing, I am afraid.

Given that this is about checking is something is an object and we already have is_object($value) in the function I did a small hotfix.

Committed 81eb563 and pushed to 9.2.x. Thanks!

@alexpott, thanks.

@alexpott:

Thanks for the fix. I did a sanity check, and it looks good.

I also noticed these lines at the end:

    $class_name = $export !== NULL && $is_object
      ? $class_name = get_class($value) . ":\n"
      : '';

How do you want to handle the extra $class_name =?

1. Another hotfix
2. A follow-up issue
3. Add to the existing follow-up #3182296: Improve logging of SimpleXML elements in the Log process plugin.

(I just marked the existing follow-up as un-postponed.)