Improve the exception message in ProcessBase.php line 184

[jibran]

Is your feature request related to a problem? Please describe. The \InvalidArgumentException 'Unable to decode output into JSON.' is not very helpful. I have updated drush to 9.6.0 and Drupal core 8.7.0-alpha1 and running the drush updatedb -y exists with following error.

In ProcessBase.php line 184:

  Unable to decode output into JSON.  

This is not very helpful. I have to turn the debugger on and put a breakpoint at ProcessBase.php line 181 to see the actual error.

[2019-03-19 12:46:26] menu.ERROR: Drupal\Core\Database\DatabaseExceptionWrapper: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'base_table.revision_id' in 'field list': SELECT base_table.revision_id AS revision_id, base_table.id AS id FROM {menu_link_content} base_table INNER JOIN {menu_link_content_data} menu_link_content_data ON menu_link_content_data.id = base_table.id WHERE menu_link_content_data.rediscover = :db_condition_placeholder_0; Array (     [:db_condition_placeholder_0] => 1 )  in Drupal\menu_link_content\Plugin\Deriver\MenuLinkContentDeriver->getDerivativeDefinitions() (line 63 of /data/app/core/modules/menu_link_content/src/Plugin/Deriver/MenuLinkContentDeriver.php). {"referer":"","ip":"127.0.0.1","request_uri":"http://127.0.0.1/","uid":0,"user":""}
{
    "0": {
        "system": {
            "8701": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "add_expand_all_items_key_in_system_menu_block": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "content_moderation": {
            "8700": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "entity_display_dependencies": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "set_default_moderation_state": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "set_views_filter_latest_translation_affected_revision": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "file": {
            "8700": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "media": {
            "8700": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "enable_standalone_url": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "node": {
            "8700": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "taxonomy": {
            "8701": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "make_taxonomy_term_revisionable": {
                "results": {
                    "query": "Taxonomy terms have been converted to be revisionable.",
                    "success": true
                }
            },
            "remove_hierarchy_from_vocabularies": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        },
        "menu_link_content": {
            "make_menu_link_content_revisionable": {
                "results": {
                    "query": "Custom menu links have been converted to be revisionable.",
                    "success": true
                }
            }
        },
        "views": {
            "exposed_filter_blocks_label_display": {
                "results": {
                    "query": null,
                    "success": true
                }
            },
            "make_placeholders_translatable": {
                "results": {
                    "query": null,
                    "success": true
                }
            }
        }
    },
    "drush_batch_process_finished": true
}

Describe the solution you'd like Throw helpful message with the appropriate info from $output variable. Describe alternatives you've considered Using debugger and putting the breakpoint before the exception.

Additional context This is an exsiting bug in D8 and it is not yet fixed so it can be reproduced now.

• Drush version 9.6.0.
• Update Drupal 8.6.12 site to 8.7.0-alpha1.
• Run drush updatedb -y

[greg-1-anderson]

I'm not opposed to improving the handling of invalid json here; however, I think that perhaps we should also consider making updatedb more defensive, or see if we can perhaps figure out why the error message is being mixed with the json output & prevent that before we get here.

[jibran]

I'd say let's do both.

FWIW, https://www.drupal.org/project/drupal/issues/2554235 fixed the issue for me.

[kimpepper]

The problem occurs when configuring Drupal to log to stdout and a message is logged, e.g. during drush updb. I assume process base is assuming this wouldn't happen?

[greg-1-anderson]

Could you configure Drupal to log to stderr? The site-process library assumes that normal conventions for stdout / stderr are being followed. In this case, that means that the output is the json text and stderr should contain the log messages.

[jibran]

Could you configure Drupal to log to stderr?

Sending log info messages to stderr seems wrong.

[greg-1-anderson]

I suspect there is a disconnect between the assumptions made when configuring Drupal to log to stdout with monolog, and the assumptions of commandline programs. I'm somewhat perplexed by the monolog use case, though, as I would expect that in the case of php-cgi / php-fpm, if monolog sent log information to stdout it would just end out getting mixed in with the browser output.

For commandline programs, though, anything that is not part of the command output should be stderr.

[kimpepper]

We're logging to stdout from our Docker containers so log messages can be captured and forwarded on. I believe this is a common practice. Not really sure if it's just monolog or anything that configures Drupal to log to stdout would run into the same issue?

[greg-1-anderson]

You can do whatever you want with your Docker container configuration vis-a-vis your web server use case; however, if you have configured Docker to insert anything at all into the stdout stream when called via Drush, then you have willfully broken Drush.

While this may be a common practice, I fear it is not one I am familiar with. My suggestion would be to figure out if there is some way to alter or disable this configuration when called via Drush, e.g. perhaps you could define an environment variable that disabled or reconfigured your logging setup. You should then be able to add -e options to your docker compose invocation from your site alias to keep stdout clear for Drush.

[kimpepper]

You can do whatever you want with your Docker container configuration vis-a-vis your web server use case; however, if you have configured Docker to insert anything at all into the stdout stream when called via Drush, then you have willfully broken Drush.

🤔 that sounds a bit harsh. It's certainly not an attempt to willfully brake Drush!

As per the 12 Factor App manifesto https://12factor.net/logs

A twelve-factor app never concerns itself with routing or storage of its output stream. It should not attempt to write to or manage logfiles. Instead, each running process writes its event stream, unbuffered, to stdout. During local development, the developer will view this stream in the foreground of their terminal to observe the app’s behavior.

I don't think we're alone here as 12 Factor Apps are a popular paradigm.

[greg-1-anderson]

Now look, https://12factor.net/port-binding says that your web server should be bound to a different port, and all web traffic should be read and written to that port. If your web server is running php, then standard out from php will be written to that port.

If you somehow conflate the standard out from php with the standard out from https://12factor.net/logs, then your log messages will appear at random throughout your website. Certainly, in such a scenario, you would look toward fixing your configuration. It would not be sensible to file a bug report with your web server provider, and insist they somehow must filter out these messages.

The situation with Drush is similar. When you call Drush via ssh or docker compose or whatever other mechanism site-process provides for you, you must have configured your system such that the stdout from php is not intermixed with the stdout of your logs. There is no good way for the client-side Drush to separate out the text of the json sent from the server-side Drush from any extraneous characters that may have been inserted by other stray processes.

Regarding the use of "willful", I intended the second definition: "having or showing a stubborn and determined intention to do as one wants, regardless of the consequences or effects." Perhaps that was too harsh. However, if you combine the stdout from your logs with the stdout of your php-cli, that will have consequences for Drush, and there's not really anything that can be done to fix that on the Drush side of things.

All I can do is reiterate my previous advice: you need to be able to identify php-cli execution paths from webserver execution paths (maybe even the usual php_sapi_name() == "cli" would be sufficient), and reconfigure your logging setup to not do that.