_call_annex_records_items_ incompatible with logging

[bpoldrack]

When running a push to an export remote with datalad's log level set to DEBUG, the patch fails b/c there's unexpected output on stderr (the logging):

Here is the relevant log:

[{'action': 'copy',
  'exception': CommandError:  [Unexpected stderr output] [err: '[DEBUG] Run ['git', 'version'] (protocol_class=StdOutErrCapture) (cwd=None) 
[DEBUG] Finished ['git', 'version'] with status 0 
[DEBUG] Not retro-fitting GitRepo with deprecated symbols, datalad-deprecated package not found 
[DEBUG] Apply datalad-next patch to annexrepo.py:AnnexRepo.enable_remote 
[DEBUG] Building doc for <class 'datalad.local.configuration.Configuration'> 
[DEBUG] Building doc for <class 'datalad_next.patches.configuration.Configuration'> 
[DEBUG] Building doc for <class 'datalad.local.configuration.Configuration'> 
[DEBUG] Failed to import requests_ftp, thus no ftp support: ModuleNotFoundError(No module named 'requests_ftp') 
[DEBUG] Apply datalad-next patch to create_sibling_ghlike.py:_GitHubLike._set_request_headers 
[DEBUG] Apply datalad-next patch to interface.(utils|base).py:_execute_command_ 
[DEBUG] Apply datalad-next patch to interface.(utils|base).py:_execute_command_ 
[DEBUG] Building doc for <class 'datalad.core.local.status.Status'> 
[DEBUG] Building doc for <class 'datalad.core.local.diff.Diff'> 
[DEBUG] Building doc for <class 'datalad.core.distributed.push.Push'> 
[DEBUG] Apply patch to datalad.core.distributed.push._transfer_data 
[DEBUG] Patching datalad.core.distributed.push.Push docstring and parameters 
[DEBUG] Building doc for <class 'datalad.core.distributed.push.Push'> 
[DEBUG] Patching datalad.support.AnnexRepo.get_export_records (new method) 
[DEBUG] Apply patch to datalad.core.distributed.push._push 
[DEBUG] Apply patch to datalad.distribution.siblings._enable_remote 
[DEBUG] Building doc for <class 'datalad.distribution.update.Update'> 
[DEBUG] Building doc for <class 'datalad.distribution.siblings.Siblings'> 
[DEBUG] UI set to UnderAnnexUI(out=<TextIOWrapper>, specialremote=None)'] [push_to_export_remote.py:_transfer_data:230,annexrepo.py:_call_annex_records_items_:1210,annexrepo.py:_call_annex_records_items_:1177,<frozen _collections_abc>:__next__:330,nonasyncrunner.py:send:97,nonasyncrunner.py:_locked_send:120,annexrepo.py:process_exited:3894],
  'message': 'CommandError(CommandError:  [Unexpected stderr output] [err: '
             "'[DEBUG] Run ['git', 'version'] "
             '(protocol_class=StdOutErrCapture) (cwd=None) \n'
             "[DEBUG] Finished ['git', 'version'] with status 0 \n"
             '[DEBUG] Not retro-fitting GitRepo with deprecated symbols, '
             'datalad-deprecated package not found \n'
             '[DEBUG] Apply datalad-next patch to '
             'annexrepo.py:AnnexRepo.enable_remote \n'
             '[DEBUG] Building doc for <class '
             "'datalad.local.configuration.Configuration'> \n"
             '[DEBUG] Building doc for <class '
             "'datalad_next.patches.configuration.Configuration'> \n"
             '[DEBUG] Building doc for <class '
             "'datalad.local.configuration.Configuration'> \n"
             '[DEBUG] Failed to import requests_ftp, thus no ftp support: '
             "ModuleNotFoundError(No module named 'requests_ftp') \n"
             '[DEBUG] Apply datalad-next patch to '
             'create_sibling_ghlike.py:_GitHubLike._set_request_headers \n'
             '[DEBUG] Apply datalad-next patch to '
             'interface.(utils|base).py:_execute_command_ \n'
             '[DEBUG] Apply datalad-next patch to '
             'interface.(utils|base).py:_execute_command_ \n'
             '[DEBUG] Building doc for <class '
             "'datalad.core.local.status.Status'> \n"
             '[DEBUG] Building doc for <class '
             "'datalad.core.local.diff.Diff'> \n"
             '[DEBUG] Building doc for <class '
             "'datalad.core.distributed.push.Push'> \n"
             '[DEBUG] Apply patch to '
             'datalad.core.distributed.push._transfer_data \n'
             '[DEBUG] Patching datalad.core.distributed.push.Push docstring '
             'and parameters \n'
             '[DEBUG] Building doc for <class '
             "'datalad.core.distributed.push.Push'> \n"
             '[DEBUG] Patching datalad.support.AnnexRepo.get_export_records '
             '(new method) \n'
             '[DEBUG] Apply patch to datalad.core.distributed.push._push \n'
             '[DEBUG] Apply patch to '
             'datalad.distribution.siblings._enable_remote \n'
             '[DEBUG] Building doc for <class '
             "'datalad.distribution.update.Update'> \n"
             '[DEBUG] Building doc for <class '
             "'datalad.distribution.siblings.Siblings'> \n"
             '[DEBUG] UI set to UnderAnnexUI(out=<TextIOWrapper>, '
             "specialremote=None)'])",
  'path': '/tmp/some',
  'refds': '/tmp/some',
  'status': 'error',
  'target': 'dataverse-export-storage',
  'type': 'dataset'}])

[bpoldrack]

This is probably an issue in core (with the call_annex functions), but haven't figured the culprit really, so not yet moving the issue.

Edit: So, it seems _call_annex_records_items_ specifically expects no stderr (which is wrong, since we can't know what to expect from any special remote that may be involved).

Moving the issue to core.

[bpoldrack]

_call_annex_records_items_ sets the protocol to GeneratorAnnexJsonNoStderrProtocol.

Feels like a protocol switch should do the trick, but not sure yet.

[yarikoptic]

FWIW that protocol/change was introduced in a single 177eb36 which is within #6580 to resolve #6578, released in 0.16.0 (awhile back) . Indeed I don't think we should generally consider presence of stderr to be an indication of errorneous execution. on a brief look I didn't find description of a reason why it was considered to be an error in that case. May be @christian-monch has some recollection of the motivation etc.

[bpoldrack]

@yarikoptic: @christian-monch commented in #7329 that it was there because previous implementation (w/o the new runner) had it.

[yarikoptic-gitmate]

Issue fixed in 0.18.3