Problem/Motivation

I'm receiving Unable to decode output into JSON: Syntax error errors from drush commands that are using the batch api internally. This results in the command to return a non-0 exit code breaking automation.

Steps to reproduce

On a multilingual site,

  • install twig_tweak (or any module with missing translations)
  • install monolog
  • set up a custom handler that logs to php://stderr using @monolog.formatter.json
  • use drush locale:check.

After this, the above error is shown.
Note, although this is one way to reproduce, the main reason for this error is the batch process printing out multiple lines of JSON, then Drupal trying to json_decode the output of the process. Any setup that makes any batch process log at least 1 line of JSON output will encounter the same error.

Proposed resolution

Fix the issue.

Remaining tasks

Fix the issue.

User interface changes

-

API changes

-

Data model changes

-

Additional information

Stack trace of the error:

Exception trace:
  at /var/www/html/vendor/consolidation/site-process/src/ProcessBase.php:171
 Consolidation\SiteProcess\ProcessBase->getOutputAsJson() at /var/www/html/vendor/drush/drush/includes/batch.inc:157
 _drush_backend_batch_process() at /var/www/html/vendor/drush/drush/includes/batch.inc:80
 drush_backend_batch_process() at /var/www/html/vendor/drush/drush/src/Drupal/Commands/core/LocaleCommands.php:89
 Drush\Drupal\Commands\core\LocaleCommands->check() at n/a:n/a
 call_user_func_array() at /var/www/html/vendor/consolidation/annotated-command/src/CommandProcessor.php:257
 Consolidation\AnnotatedCommand\CommandProcessor->runCommandCallback() at /var/www/html/vendor/consolidation/annotated-command/src/CommandProcessor.php:212
 Consolidation\AnnotatedCommand\CommandProcessor->validateRunAndAlter() at /var/www/html/vendor/consolidation/annotated-command/src/CommandProcessor.php:176
 Consolidation\AnnotatedCommand\CommandProcessor->process() at /var/www/html/vendor/consolidation/annotated-command/src/AnnotatedCommand.php:311
 Consolidation\AnnotatedCommand\AnnotatedCommand->execute() at /var/www/html/vendor/symfony/console/Command/Command.php:255
 Symfony\Component\Console\Command\Command->run() at /var/www/html/vendor/symfony/console/Application.php:1027
 Symfony\Component\Console\Application->doRunCommand() at /var/www/html/vendor/symfony/console/Application.php:273
 Symfony\Component\Console\Application->doRun() at /var/www/html/vendor/symfony/console/Application.php:149
 Symfony\Component\Console\Application->run() at /var/www/html/vendor/drush/drush/src/Runtime/Runtime.php:118
 Drush\Runtime\Runtime->doRun() at /var/www/html/vendor/drush/drush/src/Runtime/Runtime.php:48
 Drush\Runtime\Runtime->run() at /var/www/html/vendor/drush/drush/drush.php:72
 require() at /var/www/html/vendor/drush/drush/drush:4

Issue fork monolog-3223751

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

About issue forks

Comments

mhavelant created an issue. See original summary.

mhavelant’s picture

mhavelant commented
Issue summary: View changes
lussoluca’s picture

lussoluca
he/him
Primary language Italian
Location Italy
commented
Status: Active » Postponed (maintainer needs more info)

Hi, I'm not able to reproduce this issue.
Can you provide some more info?

goz’s picture

goz commented
Status: Postponed (maintainer needs more info) » Active

I have the same message, and it seems to come from PHP8+

All i do is enabling monolog, with no specific json settings.

Here is an example of setting :

services:
  monolog.handler.phpdebug_stream:
    class: Monolog\Handler\StreamHandler
    arguments: [ 'php://stdout', '%monolog.level.info%' ]

parameters:
  monolog.channel_handlers:
    default: [ 'phpdebug_stream' ]

On instance with PHP 7.4-fpm :

[2022-01-24T13:34:56.002613+00:00] system.INFO: monolog module installed. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
>  [notice] Traduction fr vérifiée pour monolog.
>  [notice] Traduction fr téléchargée pour monolog.
>  [notice] Traduction fr importée pour monolog.
> [2022-01-24T13:35:17.969912+00:00] locale.NOTICE: Translations imported: 0 added, 9 updated, 0 removed. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
> [2022-01-24T13:35:17.972171+00:00] locale.WARNING: No configuration objects have been updated. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
> 
>  [notice] Message: 1 fichier de traduction importé. /0/ traductions ont été ajoutées, /9/ 
> traductions ont été mises à jour et /0/ traductions ont été supprimées.
> 
>  [notice] Message: Aucun objet de configuration n'a été mis à jour.
> 
 [success] Successfully enabled: monolog

But in PHP 8.0 or 8.1 :

[2022-01-24T13:29:24.587661+00:00] system.INFO: monolog module installed. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
>  [notice] Checked fr translation for monolog.
>  [notice] Downloaded fr translation for monolog.
>  [notice] Imported fr translation for monolog.
>  [notice] Message: One translation file imported. /0/ translations were added, /9/ translations 
> were updated and /0/ translations were removed.
> 
>  [notice] Message: No configuration objects have been updated.
> 

In ProcessBase.php line 171:
                                                                                                                                                                                                
  Unable to decode output into JSON: Syntax error                                                                                                                                               
                                                                                                                                                                                                
  [2022-01-24T13:29:27.670428+00:00] locale.NOTICE: Translations imported: 0 added, 9 updated, 0 removed. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}  
  [2022-01-24T13:29:27.671062+00:00] locale.WARNING: No configuration objects have been updated. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}           
  {                                                                                                                                                                                             
      "0": {                                                                                                                                                                                    
          "files": {                                                                                                                                                                            
              "translations://monolog-2.0.1.fr.po": {                                                                                                                                           
                  "project": "monolog",                                                                                                                                                         
                  "langcode": "fr",                                                                                                                                                             
                  "version": "2.0.1",                                                                                                                                                           
                  "type": "local",                                                                                                                                                              
                  "filename": "monolog-2.0.1.fr.po",                                                                                                                                            
                  "uri": "translations://monolog-2.0.1.fr.po",                                                                                                                                  
                  "timestamp": 1643030966,                                                                                                                                                      
                  "directory": "translations://",                                                                                                                                               
                  "last_checked": 1643030965                                                                                                                                                    
              }                                                                                                                                                                                 
          },                                                                                                                                                                                    
          "languages": {                                                                                                                                                                        
              "translations://monolog-2.0.1.fr.po": "fr"                                                                                                                                        
          },                                                                                                                                                                                    
          "stats": {                                                                                                                                                                            
              "translations://monolog-2.0.1.fr.po": {                                                                                                                                           
                  "additions": 0,                                                                                                                                                               
                  "updates": 9,                                                                                                                                                                 
                  "deletes": 0,                                                                                                                                                                 
                  "skips": 0,                                                                                                                                                                   
                  "strings": [                                                                                                                                                                  
                      "36",                                                                                                                                                                     
                      "260",                                                                                                                                                                    
                      "417",                                                                                                                                                                    
                      "917",                                                                                                                                                                    
                      "938",                                                                                                                                                                    
                      "1164",                                                                                                                                                                   
                      "1399",                                                                                                                                                                   
                      "2441",                                                                                                                                                                   
                      "2455",                                                                                                                                                                   
                      "2456"                                                                                                                                                                    
                  ],                                                                                                                                                                            
                  "seek": 753                                                                                                                                                                   
              }                                                                                                                                                                                 
          }                                                                                                                                                                                     
      },                                                                                                                                                                                        
      "1": [],                                                                                                                                                                                  
      "drush_batch_process_finished": true                                                                                                                                                      
  }
goz’s picture

goz commented

ProcessPage.php comes from consolidation/site-process library. There is similar issue on github for this project : https://github.com/consolidation/site-process/issues/56

And here is other issue about this (linked in issue 56) :
https://github.com/drush-ops/drush/issues/4281

In my case, in \Consolidation\SiteProcess\ProcessBase:getOutputAsJson(), $output is : 

[2022-01-24T16:27:07.895354+00:00] locale.NOTICE: Translations imported: 0 added, 10 updated, 0 removed. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
[2022-01-24T16:27:07.896824+00:00] locale.WARNING: No configuration objects have been updated. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
{
    "0": {
        "files": {
            "translations://monolog-2.0.0-beta2.fr.po": {
                "project": "monolog",
                "langcode": "fr",
                "version": "2.0.0-beta2",
                "type": "local",
                "filename": "monolog-2.0.0-beta2.fr.po",
                "uri": "translations://monolog-2.0.0-beta2.fr.po",
                "timestamp": 1643041624,
                "directory": "translations://",
                "last_checked": 1643041624
            }
        },
        "languages": {
            "translations://monolog-2.0.0-beta2.fr.po": "fr"
        },
        "stats": {
            "translations://monolog-2.0.0-beta2.fr.po": {
                "additions": 0,
                "updates": 10,
                "deletes": 0,
                "skips": 0,
                "strings": [
                    "53",
                    "283",
                    "437",
                    "939",
                    "964",
                    "1191",
                    "1424",
                    "2465",
                    "2480",
                    "2481"
                ],
                "seek": 765
            }
        }
    },
    "1": [],
    "drush_batch_process_finished": true
}

and $sanitizedOutput is :

{"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
[2022-01-24T16:27:07.896824+00:00] locale.WARNING: No configuration objects have been updated. [] {"referer":"","ip":"127.0.0.1","request_uri":"http://default/","uid":0,"user":""}
{
    "0": {
        "files": {
            "translations://monolog-2.0.0-beta2.fr.po": {
                "project": "monolog",
                "langcode": "fr",
                "version": "2.0.0-beta2",
                "type": "local",
                "filename": "monolog-2.0.0-beta2.fr.po",
                "uri": "translations://monolog-2.0.0-beta2.fr.po",
                "timestamp": 1643041624,
                "directory": "translations://",
                "last_checked": 1643041624
            }
        },
        "languages": {
            "translations://monolog-2.0.0-beta2.fr.po": "fr"
        },
        "stats": {
            "translations://monolog-2.0.0-beta2.fr.po": {
                "additions": 0,
                "updates": 10,
                "deletes": 0,
                "skips": 0,
                "strings": [
                    "53",
                    "283",
                    "437",
                    "939",
                    "964",
                    "1191",
                    "1424",
                    "2465",
                    "2480",
                    "2481"
                ],
                "seek": 765
            }
        }
    },
    "1": [],
    "drush_batch_process_finished": true
}

We can see removeNonJsonJunk() remove the first string which has not been declared in json format, but miss the second one.

I'm not sure the issue is really from Consolidation/site-process. That's depend from point of view :
1/ Should site-process really sanitize string and return a valid json in anycase ? : site-process has to be fixed
2/ Do site-process call should be done with cleaner string ? So try to not have multiple string/json concatened ? : monolog (or other drupal module) has to be fixed
3/ 1/ and 2/

goz’s picture

goz commented
Status: Active » Postponed (maintainer needs more info)

My bad, i do not reproduce using php://stderr as suggested in https://github.com/drush-ops/drush/issues/4790#issuecomment-932729614. Even specifying json formatter

parameters:
  monolog.channel_handlers:
    default:
      handlers: [ 'phpdebug_stream' ]
      formatter: 'monolog.formatter.json'
services:
  monolog.handler.phpdebug_stream:
    class: Monolog\Handler\StreamHandler
    arguments: [ 'php://stderr', '%monolog.level.info%' ]
lussoluca’s picture

lussoluca
he/him
Primary language Italian
Location Italy
commented
Assigned: Unassigned » lussoluca
Status: Postponed (maintainer needs more info) » Active

OK that using stderr fix the issue, but I prefer to implement a custom line formatter specifically for Drush commands.

I'll work on this.

  • 7e88c47 committed on 3223751--unable-to 
    Issue #3223751 by lussoluca:  Unable to decode output into JSON: Syntax...

lussoluca opened merge request !5

goz’s picture

goz commented

Great, thanks lussoluca !

renrhaf’s picture

renrhaf
Primary language French
Location 📍 Strasbourg 🐦🦜
commented

Also having the issue; fixed using stderr instead of stdout.

lussoluca’s picture

lussoluca
he/him
Primary language Italian
Location Italy
commented
Status: Active » Postponed (maintainer needs more info)

@renrhaf, with which version of the module?

renrhaf’s picture

renrhaf
Primary language French
Location 📍 Strasbourg 🐦🦜
commented

Hi @lussoluca, I'm using the 2.0.2 version of the module
After using the patch the problem was still here so switched to stderr and it's good

  • lussoluca committed c26929f on 3.0.x 
    Issue #3223751 by lussoluca:  Unable to decode output into JSON: Syntax...

  • lussoluca committed 515c426 on 3.0.x 
    Issue #3223751 by lussoluca:  Unable to decode output into JSON: Syntax...

  • lussoluca committed 80412e9 on 2.x 
    Issue #3223751 by lussoluca:  Unable to decode output into JSON: Syntax...
lussoluca’s picture

lussoluca
he/him
Primary language Italian
Location Italy
commented
Status: Postponed (maintainer needs more info) » Fixed

Patch committed and pushed to 2.x and 3.0.x

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.