Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

config does not pick up the value failing test_resulthooks.py:test_basics test on nd20.04 (focal) #4753

Closed
yarikoptic opened this issue Jul 20, 2020 · 5 comments
Closed

config does not pick up the value failing test_resulthooks.py:test_basics test on nd20.04 (focal) #4753

yarikoptic opened this issue Jul 20, 2020 · 5 comments
Labels
severity-important major effect on the usability of a package, without rendering it completely unusable to everyone spurious-test-failure Tests that fail unreliably

Comments

@yarikoptic
Copy link
Member

original mentioning: #4748 (comment) -- happens only on nd20.04 (ubuntu focal), and only when I run full sweep of tests via debian/rules binary (I failed to reproduce by trying to run only that test or file or module directly using python3 -m nose etc).

# debian/rules binary
...
datalad.core.local.tests.test_resulthooks.test_basics ... > /usr/lib/python3/dist-packages/nose/tools/trivial.py(29)eq_()
-> raise AssertionError(msg or "%r != %r" % (a, b))
(Pdb) p a
None
(Pdb) p b
'bids'
(Pdb) up 
> /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/core/local/tests/test_resulthooks.py(100)test_basics()
-> eq_(clone_sub2.config.get('datalad.metadata.nativetype'), 'bids')
(Pdb) p clone_sub2.config.get('datalad.metadata.nativetype')
None
(Pdb) p clone_sub2 
Dataset('/tmp/datalad_temp_test_basicstx6qrrgx/subds2')
(Pdb) 
[1]+  Stopped                 debian/rules binary
# cat /tmp/datalad_temp_test_basicstx6qrrgx/subds2/.datalad/config 
[datalad "dataset"]
	id = 3120c732-ca99-11ea-b9ab-002590f97d84
[datalad "metadata"]
	nativetype = bids

reload of the config resolves it:

(Pdb) p clone_sub2.config.get('datalad.metadata.nativetype')
None
(Pdb) p clone_sub2.config.reload()
None
(Pdb) p clone_sub2.config.get('datalad.metadata.nativetype')
'bids'

# stat /tmp/datalad_temp_test_basicstx6qrrgx/subds2/.datalad/config
  File: /tmp/datalad_temp_test_basicstx6qrrgx/subds2/.datalad/config
  Size: 103       	Blocks: 8          IO Block: 4096   regular file
Device: 4151h/16721d	Inode: 135451      Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2020-07-20 14:56:37.414203041 +0000
Modify: 2020-07-20 14:56:37.022196616 +0000
Change: 2020-07-20 14:56:37.022196616 +0000
 Birth: -

the code leading to it is

    # setup done, now see if it works
    clone.get('subds')
    clone_sub = Dataset(clone.pathobj / 'subds')
    eq_(clone_sub.config.get('datalad.metadata.nativetype'), 'bids')
    # now the same thing with a result_xfm, should make no difference
    clone.get('subds2')
    clone_sub2 = Dataset(clone.pathobj / 'subds2')
    eq_(clone_sub2.config.get('datalad.metadata.nativetype'), 'bids')

as it fails the entire build - marking as "important"
@yarikoptic yarikoptic added the severity-important major effect on the usability of a package, without rendering it completely unusable to everyone label Jul 20, 2020
@yarikoptic
Copy link
Member Author

FWIW Here is a tail (1400 lines) of the datalad log at level 2 leading to that failure 
[Level 2] Entered eval_func for <function Create.__call__ at 0x7fa004c11430> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.create.Create'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.create.Create'> 
[DEBUG  ] Resolved dataset for creating a subdataset: /tmp/datalad_temp_test_basics5vtpotse 
[DEBUG  ] Query status of GitRepo('/tmp/datalad_temp_test_basics5vtpotse') for 1 paths 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[DEBUG  ] GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '--', 'subds2'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '-z', '-m', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-files', '-z', '-m', '--', 'subds2'] with status 0 
[DEBUG  ] GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', 'subds2'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Done GitRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics5vtpotse/subds2 into fields {'path': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[INFO   ] Creating a new annex repo at /tmp/datalad_temp_test_basics5vtpotse/subds2 
[DEBUG  ] Initialize empty Git repository at '/tmp/datalad_temp_test_basics5vtpotse/subds2' 
[Level 5] Running: ['git', 'init'] 
[Level 8] Finished running ['git', 'init'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[DEBUG  ] Initializing annex repository at /tmp/datalad_temp_test_basics5vtpotse/subds2... 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] with status 0 
[DEBUG  ] Async run ['git-annex', 'init', '-c', 'annex.dotfiles=true', '--debug'] 
[DEBUG  ] Launching process ['git-annex', 'init', '-c', 'annex.dotfiles=true', '--debug'] 
[DEBUG  ] Process 1588267 started 
[DEBUG  ] Waiting for process 1588267 to complete 
[INFO   ] [2020-07-20 15:17:19.1497148] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:19.15346151] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:19.153579096] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","show-ref","--verify","-q","origin/git-annex"] 
[INFO   ] [2020-07-20 15:17:19.156748499] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:19.157443601] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","write-tree"] 
[INFO   ] [2020-07-20 15:17:19.161553323] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.161656369] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","commit-tree","4b825dc642cb6eb9a060e54bf8d69288fbee4904","--no-gpg-sign"] 
[INFO   ] [2020-07-20 15:17:19.165463034] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.165570182] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","update-ref","refs/heads/git-annex","b58469aa5067f7fe683c4d159a926ead2ec8acff"] 
[INFO   ] [2020-07-20 15:17:19.177785897] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.178386355] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","config","annex.uuid","76c7b3df-f343-42a1-8c2e-68d2b44a6af4"] 
[INFO   ] [2020-07-20 15:17:19.182191049] process done ExitSuccess
| [2020-07-20 15:17:19.182266848] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:19.185268368] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.186264937] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","show-ref","git-annex"] 
[INFO   ] [2020-07-20 15:17:19.189429579] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.189507495] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:19.192665455] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.192834606] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","log","refs/heads/git-annex..b58469aa5067f7fe683c4d159a926ead2ec8acff","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:19.195597763] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.195809164] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","cat-file","--batch"] 
[INFO   ] [2020-07-20 15:17:19.196294121] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"] 
[INFO   ] [2020-07-20 15:17:19.19849169] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","config","annex.version","5"] 
[INFO   ] [2020-07-20 15:17:19.20280166] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.202931022] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:19.20637654] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.206743009] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:19.209704225] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.209829064] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","show-ref","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:19.213152202] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:19.213305895] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:19.216744119] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.216868455] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","show-ref","--hash","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:19.22064806] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:19.220751257] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","checkout","-q","-B","master"] 
[INFO   ] [2020-07-20 15:17:19.224254798] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.22540781] read: uname ["-n"] 
[INFO   ] [2020-07-20 15:17:19.227734784] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.230012104] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","hash-object","-w","--stdin-paths","--no-filters"] 
[INFO   ] [2020-07-20 15:17:19.230605078] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:19.234676767] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.234800191] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:19.237324909] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.237493345] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","write-tree"] 
[INFO   ] [2020-07-20 15:17:19.240180694] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.240287837] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","commit-tree","08dc7f5ef1120e8259be0a35f7675e418bd56a14","--no-gpg-sign","-p","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:19.246574491] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.246769363] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.dotfiles=true","update-ref","refs/heads/git-annex","7bac5ed757b26e16b5d18d4b30679fb91d48af87"] 
[INFO   ] [2020-07-20 15:17:19.251432239] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.253149144] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.253642257] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:19.254186883] process done ExitSuccess 
[DEBUG  ] Process 1588267 exited with return code 0 
[Level 8] Finished running ['git-annex', 'init', '-c', 'annex.dotfiles=true', '--debug'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'check-attr', '-z', '--all', '--', '.'] 
[Level 8] Finished running ['git', 'check-attr', '-z', '--all', '--', '.'] with status 0 
[DEBUG  ] Setting annex backend to MD5E (persistently) 
[Level 5] Running: ['git', 'config', '--local', 'annex.backends', 'MD5E'] 
[Level 8] Finished running ['git', 'config', '--local', 'annex.backends', 'MD5E'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes'] 
[Level 8] Finished running ['git', '-c', 'annex.largefiles=nothing', 'add', '--dry-run', '-N', '--ignore-missing', '--verbose', '--', '.gitattributes'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitattributes'] 
[Level 8] Finished running ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitattributes'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 3) 
[Level 5] Running: ['git', 'check-attr', '-z', '--all', '--', '.datalad/config', '.datalad/metadata/aggregate*', '.datalad/metadata/objects/**'] 
[Level 8] Finished running ['git', 'check-attr', '-z', '--all', '--', '.datalad/config', '.datalad/metadata/aggregate*', '.datalad/metadata/objects/**'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'check-attr', '-z', '--all', '--', '.git'] 
[Level 8] Finished running ['git', 'check-attr', '-z', '--all', '--', '.git'] with status 0 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics5vtpotse/subds2 
[Level 5] Running: ['git', 'config', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config', '--add', 'datalad.dataset.id', '1a82068c-ca9c-11ea-b071-002590f97d84'] 
[Level 8] Finished running ['git', 'config', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config', '--add', 'datalad.dataset.id', '1a82068c-ca9c-11ea-b071-002590f97d84'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'diff', '--name-only', '--staged'] 
[Level 8] Finished running ['git', 'diff', '--name-only', '--staged'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse/subds2).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse/subds2).get_content_info(...) 
[DEBUG  ] 2 path(s) to add to AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse/subds2) {'.gitattributes': {'type': 'file', 'state': 'untracked'}, '.datalad': {'type': 'directory', 'state': 'untracked'}} 
[DEBUG  ] Process file list chunk 0 (length 2) 
[Level 5] Running: ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitattributes', '.datalad'] 
[Level 8] Finished running ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitattributes', '.datalad'] with status 0 
[DEBUG  ] Committing via direct call of git: ['git', 'commit', '-m', '[DATALAD] new dataset'] 
[DEBUG  ] Async run ['git', 'commit', '-m', '[DATALAD] new dataset', '--', '.gitattributes', '.datalad'] 
[DEBUG  ] Launching process ['git', 'commit', '-m', '[DATALAD] new dataset', '--', '.gitattributes', '.datalad'] 
[DEBUG  ] Process 1588910 started 
[DEBUG  ] Waiting for process 1588910 to complete 
[Level 5] Read 202 bytes from 1588910[stdout] 
[DEBUG  ] Process 1588910 exited with return code 0 
[Level 8] Finished running ['git', 'commit', '-m', '[DATALAD] new dataset', '--', '.gitattributes', '.datalad'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] No sync necessary, no corresponding branch detected 
[Level 2] Entered eval_func for <function Save.__call__ at 0x7fa004bbf280> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.save.Save'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.save.Save'> 
[DEBUG  ] Resolved dataset for saving: /tmp/datalad_temp_test_basics5vtpotse 
[Level 2] Entered eval_func for <function Status.__call__ at 0x7fa004ba1af0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.status.Status'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.status.Status'> 
[DEBUG  ] Resolved dataset for status reporting: /tmp/datalad_temp_test_basics5vtpotse 
[DEBUG  ] query AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).diffstatus() for paths: [PosixPath('/tmp/datalad_temp_test_basics5vtpotse/subds2')] 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', 'subds2'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '-z', '-m', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-files', '-z', '-m', '--', 'subds2'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', 'subds2'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Determined 1 datasets for saving from input arguments 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Running: ['git', 'diff', '--name-only', '--staged'] 
[Level 8] Finished running ['git', 'diff', '--name-only', '--staged'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', 'subds2'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', 'subds2'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse).get_content_info(...) 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'submodule', 'add', '--name', 'subds2', './subds2', 'subds2'] 
[Level 8] Finished running ['git', 'submodule', 'add', '--name', 'subds2', './subds2', 'subds2'] with status 0 
[Level 5] Running: ['git', 'config', '--file', '.gitmodules', '--replace-all', 'submodule.subds2.datalad-id', '1a82068c-ca9c-11ea-b071-002590f97d84'] 
[Level 8] Finished running ['git', 'config', '--file', '.gitmodules', '--replace-all', 'submodule.subds2.datalad-id', '1a82068c-ca9c-11ea-b071-002590f97d84'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitmodules'] 
[Level 8] Finished running ['git', '-c', 'annex.largefiles=nothing', 'add', '--verbose', '--', '.gitmodules'] with status 0 
[DEBUG  ] 1 path(s) to add to AnnexRepo(/tmp/datalad_temp_test_basics5vtpotse) {'.gitmodules': {'type': 'file', 'state': 'modified'}} 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.gitmodules'] 
[Level 8] Finished running ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.gitmodules'] with status 0 
[DEBUG  ] Committing via direct call of git: ['git', 'commit', '-m', '[DATALAD] Recorded changes'] 
[DEBUG  ] Async run ['git', 'commit', '-m', '[DATALAD] Recorded changes', '--'] 
[DEBUG  ] Launching process ['git', 'commit', '-m', '[DATALAD] Recorded changes', '--'] 
[DEBUG  ] Process 1589617 started 
[DEBUG  ] Waiting for process 1589617 to complete 
[Level 5] Read 105 bytes from 1589617[stdout] 
[DEBUG  ] Process 1589617 exited with return code 0 
[Level 8] Finished running ['git', 'commit', '-m', '[DATALAD] Recorded changes', '--'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] No sync necessary, no corresponding branch detected 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[DEBUG  ] Not reporting result (value is not one of ('create',) [constraints.py:__call__:289]): {'action': 'add', 'path': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'type': 'file', 'refds': '/tmp/datalad_temp_test_basics5vtpotse', 'status': 'ok', 'key': None} 
[DEBUG  ] Not reporting result (value is not one of ('create',) [constraints.py:__call__:289]): {'action': 'add', 'path': '/tmp/datalad_temp_test_basics5vtpotse/.gitmodules', 'type': 'file', 'refds': '/tmp/datalad_temp_test_basics5vtpotse', 'status': 'ok', 'key': None} 
[DEBUG  ] Not reporting result (value is not one of ('create',) [constraints.py:__call__:289]): {'action': 'save', 'type': 'dataset', 'path': '/tmp/datalad_temp_test_basics5vtpotse', 'refds': '/tmp/datalad_temp_test_basics5vtpotse', 'status': 'ok'} 
[Level 2] Entered eval_func for <function Install.__call__ at 0x7fa004c05a60> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.distribution.install.Install'> 
[Level 2] Returning return_func from eval_func for <class 'datalad.distribution.install.Install'> 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics86fgkmko into fields {'path': '/tmp/datalad_temp_test_basics86fgkmko', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 2] Entered eval_func for <function Clone.__call__ at 0x7fa004c050d0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.distributed.clone.Clone'> 
[Level 2] Returning generator_func from eval_func for <class 'datalad.core.distributed.clone.Clone'> 
[DEBUG  ] Resolved clone target path to: '/tmp/datalad_temp_test_basics86fgkmko' 
[Level 5] Detected file ri 
[DEBUG  ] Git clone from /tmp/datalad_temp_test_basics5vtpotse to /tmp/datalad_temp_test_basics86fgkmko 
[DEBUG  ] Async run ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse', '/tmp/datalad_temp_test_basics86fgkmko'] 
[DEBUG  ] Launching process ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse', '/tmp/datalad_temp_test_basics86fgkmko'] 
[DEBUG  ] Process 1589678 started 
[DEBUG  ] Waiting for process 1589678 to complete 
[DEBUG  ] Non-progress stderr: b"Cloning into '/tmp/datalad_temp_test_basics86fgkmko'...\n" 
[Level 5] Read 56 bytes from 1589678[stderr] 
[DEBUG  ] Non-progress stderr: b'done.\n' 
[Level 5] Read 6 bytes from 1589678[stderr] 
[DEBUG  ] Process 1589678 exited with return code 0 
[Level 8] Finished running ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse', '/tmp/datalad_temp_test_basics86fgkmko'] with status 0 
[DEBUG  ] Git clone completed 
[INFO   ]  Clone attempt 1 Candidate locations done in 0.0381501 sec at 26.2123 Candidate locations/sec 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] 
[Level 8] Finished running ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[DEBUG  ] Initializing annex repo at /tmp/datalad_temp_test_basics86fgkmko 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] with status 0 
[DEBUG  ] Async run ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Launching process ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Process 1590054 started 
[DEBUG  ] Waiting for process 1590054 to complete 
[INFO   ] [2020-07-20 15:17:21.242170334] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:21.246242328] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:21.246345027] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--verify","-q","origin/git-annex"] 
[INFO   ] [2020-07-20 15:17:21.24832478] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:21.248607227] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:21.252453121] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.252539043] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","4b825dc642cb6eb9a060e54bf8d69288fbee4904","--no-gpg-sign"] 
[INFO   ] [2020-07-20 15:17:21.262940705] process done ExitSuccess
| [2020-07-20 15:17:21.263041659] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","41066e2645083c749c07390ed051eda57c55f66c"] 
[INFO   ] [2020-07-20 15:17:21.265844959] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.266290071] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.uuid","5f21f4f7-e0df-4196-8993-11607ff9eb04"] 
[INFO   ] [2020-07-20 15:17:21.268142687] process done ExitSuccess
| [2020-07-20 15:17:21.268216171] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:21.270083973] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.272312356] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","git-annex"] 
[INFO   ] [2020-07-20 15:17:21.27481314] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.274942732] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:21.277950955] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.278183926] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..41066e2645083c749c07390ed051eda57c55f66c","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:21.28085714] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.280995799] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..5f73502525d4ad61df309eb8ad259a0fb523ac9b","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:21.284470066] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.284730374] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch"] 
[INFO   ] [2020-07-20 15:17:21.285442824] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"] 
[INFO   ] [2020-07-20 15:17:21.28805973] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","hash-object","-w","--stdin-paths","--no-filters"] 
[INFO   ] [2020-07-20 15:17:21.288627735] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:21.289199555] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","diff-index","--raw","-z","-r","--no-renames","-l0","--cached","5f73502525d4ad61df309eb8ad259a0fb523ac9b","--"] 
[INFO   ] [2020-07-20 15:17:21.29275459] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.293458095] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.294138559] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","5f73502525d4ad61df309eb8ad259a0fb523ac9b..refs/heads/git-annex","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:21.297725808] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.297924596] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:21.301736303] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.301869363] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","057bc1fd9056157903b5e635be707e8623197a30","--no-gpg-sign","-p","refs/heads/git-annex","-p","5f73502525d4ad61df309eb8ad259a0fb523ac9b"] 
[INFO   ] [2020-07-20 15:17:21.305545037] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.305684506] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","969f4d77c13484f819f63368c457eac96ad7fd47"] 
[INFO   ] [2020-07-20 15:17:21.308785799] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.310308527] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.version","5"] 
[INFO   ] [2020-07-20 15:17:21.312269604] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.31234658] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:21.316351263] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.316494765] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:21.318457478] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.31859224] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:21.321664957] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.321770129] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:21.325263971] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.325366607] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:21.32764631] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.327770697] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","checkout","-q","-B","master"] 
[INFO   ] [2020-07-20 15:17:21.332132362] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.333410337] read: uname ["-n"] 
[INFO   ] [2020-07-20 15:17:21.335441084] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.337529738] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:21.340872359] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.341080429] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","remote.origin.annex-uuid","56f7ed7e-1696-4246-a9bb-39314fd5c7d6"] 
[INFO   ] [2020-07-20 15:17:21.344338389] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.344449765] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:21.347968169] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.348672046] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:21.351407037] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.351508883] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:21.354527457] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.354718124] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:21.359589939] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.359718459] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","8802ba5c46f70fd0666565af858bafdce9bab471","--no-gpg-sign","-p","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:21.364111489] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.364245951] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","927464fc893f15418160f900315978578101542a"] 
[INFO   ] [2020-07-20 15:17:21.368809402] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.370570223] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.371078008] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:21.371555514] process done ExitSuccess 
[DEBUG  ] Process 1590054 exited with return code 0 
[Level 8] Finished running ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'cat-file', 'blob', 'git-annex:remote.log'] 
[Level 5] CommandError: 'git cat-file blob git-annex:remote.log' failed with exitcode 128 under /tmp/datalad_temp_test_basics86fgkmko [err: 'fatal: Not a valid object name git-annex:remote.log'] 
[Level 5] Detected file ri 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.alwaysbids.call-json', 'run_procedure {{"dataset":"{path}","spec":"cfg_metadatatypes bids"}}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.alwaysbids.call-json', 'run_procedure {{"dataset":"{path}","spec":"cfg_metadatatypes bids"}}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.alwaysbids.match-json', '{"type":"dataset","action":"install","status":["eq", "ok"]}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.alwaysbids.match-json', '{"type":"dataset","action":"install","status":["eq", "ok"]}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.wtf.call-json', 'wtf {{"result_renderer": "disabled"}}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.wtf.call-json', 'wtf {{"result_renderer": "disabled"}}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.wtf.match-json', '{"type":"dataset","action":"install","status":["eq", "ok"]}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.wtf.match-json', '{"type":"dataset","action":"install","status":["eq", "ok"]}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.unlockfiles.call-json', 'unlock {{"dataset":"{dsarg}","path":"{path}"}}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.unlockfiles.call-json', 'unlock {{"dataset":"{dsarg}","path":"{path}"}}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.unlockfiles.match-json', '{"type":"file","action":"get","status":"ok"}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.unlockfiles.match-json', '{"type":"file","action":"get","status":"ok"}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.annoy.call-json', 'run {{"cmd":"touch {path}_annoyed","dataset":"{dsarg}","explicit":true}}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.annoy.call-json', 'run {{"cmd":"touch {path}_annoyed","dataset":"{dsarg}","explicit":true}}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', 'datalad.result-hook.annoy.match-json', '{"type":["in", ["file"]],"action":"get","status":"notneeded"}'] 
[Level 8] Finished running ['git', 'config', '--local', 'datalad.result-hook.annoy.match-json', '{"type":["in", ["file"]],"action":"get","status":"notneeded"}'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Entered eval_func for <function Get.__call__ at 0x7fa004c05af0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.distribution.get.Get'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.distribution.get.Get'> 
[DEBUG  ] Resolved dataset for get content: /tmp/datalad_temp_test_basics86fgkmko 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[Level 5] Detected file ri 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics86fgkmko/subds into fields {'path': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Failed to detect a valid repo at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'rev-list', '-n1', 'HEAD', '--', 'subds'] 
[Level 8] Finished running ['git', 'rev-list', '-n1', 'HEAD', '--', 'subds'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', '--contains=7a8a7ba08fa1c1576cd4f7e7093aa1c34aff4b58', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', '--contains=7a8a7ba08fa1c1576cd4f7e7093aa1c34aff4b58', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Parsed ri subds into fields {'path': 'subds', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Parsed ri ./subds into fields {'path': './subds', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[DEBUG  ] Git clone from /tmp/datalad_temp_test_basics5vtpotse/subds to /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] Async run ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds', '/tmp/datalad_temp_test_basics86fgkmko/subds'] 
[DEBUG  ] Launching process ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds', '/tmp/datalad_temp_test_basics86fgkmko/subds'] 
[DEBUG  ] Process 1591213 started 
[DEBUG  ] Waiting for process 1591213 to complete 
[DEBUG  ] Non-progress stderr: b"Cloning into '/tmp/datalad_temp_test_basics86fgkmko/subds'...\n" 
[Level 5] Read 62 bytes from 1591213[stderr] 
[DEBUG  ] Non-progress stderr: b'done.\n' 
[Level 5] Read 6 bytes from 1591213[stderr] 
[DEBUG  ] Process 1591213 exited with return code 0 
[Level 8] Finished running ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds', '/tmp/datalad_temp_test_basics86fgkmko/subds'] with status 0 
[DEBUG  ] Git clone completed 
[INFO   ]  Clone attempt 1 Candidate locations done in 0.0406618 sec at 24.5931 Candidate locations/sec 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] 
[Level 8] Finished running ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[DEBUG  ] Initializing annex repo at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] with status 0 
[DEBUG  ] Async run ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Launching process ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Process 1591583 started 
[DEBUG  ] Waiting for process 1591583 to complete 
[INFO   ] [2020-07-20 15:17:22.912928159] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:22.916851739] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:22.917204117] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--verify","-q","origin/git-annex"] 
[INFO   ] [2020-07-20 15:17:22.920541563] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:22.920863053] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:22.924882547] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.924998811] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","4b825dc642cb6eb9a060e54bf8d69288fbee4904","--no-gpg-sign"] 
[INFO   ] [2020-07-20 15:17:22.939800383] process done ExitSuccess
| [2020-07-20 15:17:22.939932449] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","33be8c6505211d93c1d0014480831438375d4eff"] 
[INFO   ] [2020-07-20 15:17:22.944260314] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.944768037] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.uuid","5acf6fec-c715-44eb-ae43-87ae4442b1d4"] 
[INFO   ] [2020-07-20 15:17:22.947161092] process done ExitSuccess
| [2020-07-20 15:17:22.947244051] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:22.949590879] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.950898594] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","git-annex"] 
[INFO   ] [2020-07-20 15:17:22.95372515] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.953796677] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:22.957583691] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.957738078] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..33be8c6505211d93c1d0014480831438375d4eff","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:22.960695531] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.96079118] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..ff8a109fe6c6e7833692d1700d346453442d8c0d","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:22.964518243] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.964800968] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch"] 
[INFO   ] [2020-07-20 15:17:22.965553185] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"] 
[INFO   ] [2020-07-20 15:17:22.968067585] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","hash-object","-w","--stdin-paths","--no-filters"] 
[INFO   ] [2020-07-20 15:17:22.968566334] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:22.969271614] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","diff-index","--raw","-z","-r","--no-renames","-l0","--cached","ff8a109fe6c6e7833692d1700d346453442d8c0d","--"] 
[INFO   ] [2020-07-20 15:17:22.973886949] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.974747361] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.975293954] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","ff8a109fe6c6e7833692d1700d346453442d8c0d..refs/heads/git-annex","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:22.978986889] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.979165422] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:22.982535149] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.982646414] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","b068b852f2ecdec91fa9918cac6b14b90c236b3a","--no-gpg-sign","-p","refs/heads/git-annex","-p","ff8a109fe6c6e7833692d1700d346453442d8c0d"] 
[INFO   ] [2020-07-20 15:17:22.98683906] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.986961697] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","9fc721c4a45190fb90527b895ef22e9fd8eaa079"] 
[INFO   ] [2020-07-20 15:17:22.989489779] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.99086675] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.version","5"] 
[INFO   ] [2020-07-20 15:17:22.993171593] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.993284455] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:22.997002891] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.997164038] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:22.999656756] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:22.999763426] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:23.003584253] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.00368989] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:23.007135094] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.007228119] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:23.010082134] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.010177021] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","checkout","-q","-B","master"] 
[INFO   ] [2020-07-20 15:17:23.014526909] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.015728878] read: uname ["-n"] 
[INFO   ] [2020-07-20 15:17:23.017901256] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.01937868] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:23.021245651] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.02142726] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","remote.origin.annex-uuid","0cedaea1-f90d-485c-adfb-34bf1f215ed7"] 
[INFO   ] [2020-07-20 15:17:23.023511396] process done ExitSuccess
| [2020-07-20 15:17:23.023606105] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:23.026514498] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.026964596] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:23.029532048] process done ExitSuccess
| [2020-07-20 15:17:23.029613835] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:23.032286736] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.032425809] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:23.035684348] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.035769468] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","a11064697810d5688f118ad2a37767ee1eaa607e","--no-gpg-sign","-p","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:23.038786651] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.038873123] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","70c264de3ba280ee321ed160a345b2380d0b517f"] 
[INFO   ] [2020-07-20 15:17:23.043050427] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.044477562] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.045029694] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:23.045452251] process done ExitSuccess 
[DEBUG  ] Process 1591583 exited with return code 0 
[Level 8] Finished running ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'cat-file', 'blob', 'git-annex:remote.log'] 
[Level 5] CommandError: 'git cat-file blob git-annex:remote.log' failed with exitcode 128 under /tmp/datalad_temp_test_basics86fgkmko/subds [err: 'fatal: Not a valid object name git-annex:remote.log'] 
[Level 5] Detected file ri 
[DEBUG  ] Update cloned subdataset /tmp/datalad_temp_test_basics86fgkmko/subds in parent 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', 'master^{commit}', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', 'master^{commit}', '--'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'submodule', 'update', '--checkout', '--init', '--', 'subds'] 
[Level 8] Finished running ['git', 'submodule', 'update', '--checkout', '--init', '--', 'subds'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] Installed subdataset in order to get /tmp/datalad_temp_test_basics86fgkmko/subds [install(/tmp/datalad_temp_test_basics86fgkmko/subds)] 
[DEBUG  ] Result {'action': 'install', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'type': 'dataset', 'status': 'ok', 'source': {'source': '/tmp/datalad_temp_test_basics5vtpotse/subds', 'version': None, 'type': 'giturl', 'giturl': '/tmp/datalad_temp_test_basics5vtpotse/subds', 'default_destpath': 'subds'}, 'message': ('Installed subdataset in order to get %s', '/tmp/datalad_temp_test_basics86fgkmko/subds'), 'contains': [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds')]} matches hook alwaysbids 
[DEBUG  ] Running hook alwaysbids: run_procedure{'dataset': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'spec': 'cfg_metadatatypes bids'} 
[Level 2] Entered eval_func for <function RunProcedure.__call__ at 0x7fa004ac2f70> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.interface.run_procedure.RunProcedure'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.interface.run_procedure.RunProcedure'> 
[DEBUG  ] Resolved dataset for run a procedure: /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/.config/datalad/procedures' 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/etc/xdg/datalad/procedures' 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/procedures' 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds) 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures' 
[INFO   ] Running procedure cfg_metadatatypes 
[DEBUG  ] Full procedure command: '/usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds bids' 
[Level 2] Entered eval_func for <function Run.__call__ at 0x7fa004ab0940> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.run.Run'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.core.local.run.Run'> 
[DEBUG  ] Resolved dataset for tracking outcomes of a command: /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] tracking command output underneath Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds) 
[DEBUG  ] chdir '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build' -> '/tmp/datalad_temp_test_basics86fgkmko/subds'  
[DEBUG  ] chdir '/tmp/datalad_temp_test_basics86fgkmko/subds' -> '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build' (coming back) 
[INFO   ] == Command start (output follows) ===== 
[Level 5] Running: /usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds bids 
[Level 5] Instantiating ssh manager 
[Level 5] Done importing main __init__ 
[Level 5] Importing support.network 
[Level 5] Done importing support.network 
[Level 5] Requested to provide version for cmd:git 
[DEBUG  ] parseParameters: Given "exclude_special_remotes: bool, optional
|   if True, don't return annex special remotes", we split into [('exclude_special_remotes', "exclude_special_remotes: bool, optional\n  if True, don't return annex special remotes")] 
[DEBUG  ] parseParameters: Given "with_urls_only : bool, optional
|   return only remotes which have urls", we split into [('with_urls_only', 'with_urls_only : bool, optional\n  return only remotes which have urls')] 
[Level 5] Importing dataset 
[Level 5] Done importing dataset 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics86fgkmko/subds into fields {'path': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[DEBUG  ] Resolved dataset for configuration: /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Found 0 previous connections 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics5vtpotse/subds into fields {'path': '/tmp/datalad_temp_test_basics5vtpotse/subds', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config', '--add', 'datalad.metadata.nativetype', 'bids'] 
[Level 8] Finished running ['git', 'config', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config', '--add', 'datalad.metadata.nativetype', 'bids'] with status 0 
[Level 5] Importing datalad.interface.results 
[Level 5] Done importing datalad.interface.results 
[DEBUG  ] Discovering plugins 
[Level 5] Importing module datalad.core.local.save  
[DEBUG  ] Building doc for <class 'datalad.core.local.status.Status'> 
[DEBUG  ] Building doc for <class 'datalad.core.local.save.Save'> 
[DEBUG  ] Found matching interface ('datalad.core.local.save', 'Save', 'save') for save 
[Level 2] Entered eval_func for <function Save.__call__ at 0x7f131ac2bca0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.save.Save'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.save.Save'> 
[DEBUG  ] Resolved dataset for saving: /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 2] Entered eval_func for <function Status.__call__ at 0x7f131ac2bf70> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.status.Status'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.status.Status'> 
[DEBUG  ] Resolved dataset for status reporting: /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] query AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds).diffstatus() for paths: [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config')] 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad/config'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds).get_content_info(...) 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '-z', '-m', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-files', '-z', '-m', '--', '.datalad/config'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', '.datalad/config'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds).get_content_info(...) 
[DEBUG  ] Determined 1 datasets for saving from input arguments 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Running: ['git', 'diff', '--name-only', '--staged'] 
[Level 8] Finished running ['git', 'diff', '--name-only', '--staged'] with status 0 
[DEBUG  ] 1 path(s) to add to AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds) {'.datalad/config': {'state': 'modified', 'type': 'file', 'gitshasum': 'd11a107bd22e52ad6ea65b7d8599f7333d93c943', 'prev_gitshasum': 'd11a107bd22e52ad6ea65b7d8599f7333d93c943'}} 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Running: ['git', 'annex', 'version', '--raw'] 
[Level 8] Finished running ['git', 'annex', 'version', '--raw'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.datalad/config'] 
[Level 3] Reading line from stdout 
[Level 3] Reading line from stdout 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 8] Finished running ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.datalad/config'] with status 0 
[DEBUG  ] Committing via direct call of git: ['git', 'commit', '-m', 'Configure metadata type(s)'] 
[DEBUG  ] Async run ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] 
[DEBUG  ] Launching process ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] 
[DEBUG  ] Process 1592599 started 
[DEBUG  ] Waiting for process 1592599 to complete 
[Level 5] Read 77 bytes from 1592599[stdout] 
[DEBUG  ] Process 1592599 exited with return code 0 
[Level 8] Finished running ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] No sync necessary, no corresponding branch detected 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Exiting 
[Level 8] Finished running '/usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds bids' with status 0 
[INFO   ] == Command exit (modification check follows) ===== 
[DEBUG  ] Result {'action': 'install', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'type': 'dataset', 'status': 'ok', 'source': {'source': '/tmp/datalad_temp_test_basics5vtpotse/subds', 'version': None, 'type': 'giturl', 'giturl': '/tmp/datalad_temp_test_basics5vtpotse/subds', 'default_destpath': 'subds'}, 'message': ('Installed subdataset in order to get %s', '/tmp/datalad_temp_test_basics86fgkmko/subds'), 'contains': [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds')]} matches hook wtf 
[DEBUG  ] Running hook wtf: wtf{'result_renderer': 'disabled'} 
[Level 2] Entered eval_func for <function WTF.__call__ at 0x7fa004b418b0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.plugin.wtf.WTF'> 
[Level 2] Returning return_func from eval_func for <class 'datalad.plugin.wtf.WTF'> 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Requested to provide version for cmd:git 
[Level 5] Requested to provide version for cmd:bundled-git 
[Level 5] Running: ['/usr/lib/git-annex.linux/git', 'version'] 
[Level 8] Finished running ['/usr/lib/git-annex.linux/git', 'version'] with status 0 
[Level 5] Requested to provide version for cmd:system-git 
[Level 5] Requested to provide version for cmd:system-ssh 
[Level 5] Running: ['ssh', '-V'] 
[Level 8] Finished running ['ssh', '-V'] with status 0 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for annexremote 
[Level 5] Requested to provide version for appdirs 
[Level 5] Requested to provide version for boto 
[DEBUG  ] Module boto seems to be not present 
[Level 5] Requested to provide version for exifread 
[Level 5] Requested to provide version for git 
[Level 5] Requested to provide version for gitdb 
[Level 5] Requested to provide version for humanize 
[Level 5] Requested to provide version for iso8601 
[Level 5] Requested to provide version for keyring 
[Level 5] Requested to provide version for keyrings.alt 
[Level 5] Requested to provide version for msgpack 
[Level 5] Requested to provide version for mutagen 
[Level 5] Requested to provide version for patool 
[DEBUG  ] Module patool seems to be not present 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for requests 
[Level 5] Requested to provide version for scrapy 
[DEBUG  ] Module scrapy seems to be not present 
[Level 5] Requested to provide version for wrapt 
[Level 5] Requested to provide version for cmd:git 
[Level 5] Requested to provide version for tqdm 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for patoolib 
[Level 5] Requested to provide version for cmd:system-git 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Requested to provide version for cmd:bundled-git 
[Level 5] Requested to provide version for cmd:system-ssh 
[Level 5] Requested to provide version for annexremote 
[Level 5] Requested to provide version for appdirs 
[Level 5] Requested to provide version for exifread 
[Level 5] Requested to provide version for git 
[Level 5] Requested to provide version for gitdb 
[Level 5] Requested to provide version for humanize 
[Level 5] Requested to provide version for iso8601 
[Level 5] Requested to provide version for keyring 
[Level 5] Requested to provide version for keyrings.alt 
[Level 5] Requested to provide version for msgpack 
[Level 5] Requested to provide version for mutagen 
[Level 5] Requested to provide version for requests 
[Level 5] Requested to provide version for wrapt 
[Level 5] Running: ['git', 'annex', 'version'] 
[Level 8] Finished running ['git', 'annex', 'version'] with status 0 
[DEBUG  ] Failed to create sample file for length 314. Last succeeded was 313. Exception: [Errno 36] File name too long: '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/dl89733_________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________' [wtf.py:get_max_path_length:72] 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko/subds 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds) 
[DEBUG  ] Not reporting result (excluded by filter <function get_result_filter.<locals>._fx at 0x7fa00232f5e0> with arguments {'path': None, 'dataset': Dataset('/tmp/datalad_temp_test_basics86fgkmko/subds'), 'fulfilled': None, 'recursive': False, 'recursion_limit': None, 'contains': PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds'), 'bottomup': False, 'set_property': None, 'delete_property': None, 'on_failure': 'ignore', 'result_filter': <function is_ok_dataset at 0x7fa004c5a820>} [utils.py:keep_result:655]): {'action': 'subdataset', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds', 'status': 'impossible', 'message': 'path not contained in any matching subdataset'} 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[DEBUG  ] Determine what files match the query to work with 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', '-c', 'annex.merge-annex-branches=false', 'annex', 'find', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--not', '--in', '.', '--debug', '--', '.'] 
[Level 8] Finished running ['git', '-c', 'annex.merge-annex-branches=false', 'annex', 'find', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--not', '--in', '.', '--debug', '--', '.'] with status 0 
[DEBUG  ] No files found needing fetching. 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Entered eval_func for <function Get.__call__ at 0x7fa004c05af0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.distribution.get.Get'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.distribution.get.Get'> 
[DEBUG  ] Resolved dataset for get content: /tmp/datalad_temp_test_basics86fgkmko 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko) 
[Level 5] Running: ['git', 'config', '-z', '-l', '--file', '.gitmodules'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--file', '.gitmodules'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko).get_content_info(...) 
[Level 5] Detected file ri 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics86fgkmko/subds2 into fields {'path': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Failed to detect a valid repo at /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'rev-list', '-n1', 'HEAD', '--', 'subds2'] 
[Level 8] Finished running ['git', 'rev-list', '-n1', 'HEAD', '--', 'subds2'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', '--contains=a4bb324cba7ef873a06c01621c211d6983dba552', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', '--contains=a4bb324cba7ef873a06c01621c211d6983dba552', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Parsed ri subds2 into fields {'path': 'subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Parsed ri ./subds2 into fields {'path': './subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[DEBUG  ] Git clone from /tmp/datalad_temp_test_basics5vtpotse/subds2 to /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] Async run ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds2', '/tmp/datalad_temp_test_basics86fgkmko/subds2'] 
[DEBUG  ] Launching process ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds2', '/tmp/datalad_temp_test_basics86fgkmko/subds2'] 
[DEBUG  ] Process 1593938 started 
[DEBUG  ] Waiting for process 1593938 to complete 
[DEBUG  ] Non-progress stderr: b"Cloning into '/tmp/datalad_temp_test_basics86fgkmko/subds2'...\n" 
[Level 5] Read 63 bytes from 1593938[stderr] 
[DEBUG  ] Non-progress stderr: b'done.\n' 
[Level 5] Read 6 bytes from 1593938[stderr] 
[DEBUG  ] Process 1593938 exited with return code 0 
[Level 8] Finished running ['git', 'clone', '--progress', '/tmp/datalad_temp_test_basics5vtpotse/subds2', '/tmp/datalad_temp_test_basics86fgkmko/subds2'] with status 0 
[DEBUG  ] Git clone completed 
[INFO   ]  Clone attempt 1 Candidate locations done in 0.04636 sec at 21.5703 Candidate locations/sec 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] 
[Level 8] Finished running ['git', 'rev-parse', '--verify', 'HEAD^{commit}'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[DEBUG  ] Initializing annex repo at /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads', 'refs/remotes'] with status 0 
[Level 5] Running: ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] 
[Level 8] Finished running ['git', 'for-each-ref', '--format=%(refname:strip=2)', 'refs/heads'] with status 0 
[DEBUG  ] Async run ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Launching process ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] 
[DEBUG  ] Process 1594497 started 
[DEBUG  ] Waiting for process 1594497 to complete 
[INFO   ] [2020-07-20 15:17:26.462424157] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:26.466540734] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:26.466920859] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--verify","-q","origin/git-annex"] 
[INFO   ] [2020-07-20 15:17:26.470150062] process done ExitFailure 1 
[INFO   ] [2020-07-20 15:17:26.470541616] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:26.473611557] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.473710835] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","4b825dc642cb6eb9a060e54bf8d69288fbee4904","--no-gpg-sign"] 
[INFO   ] [2020-07-20 15:17:26.487840727] process done ExitSuccess
| [2020-07-20 15:17:26.487975974] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","783786ed8b606bc2a8cd8d9538988558228d62da"] 
[INFO   ] [2020-07-20 15:17:26.491808159] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.492370587] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.uuid","b489008d-78c6-41f8-9fbe-3d5cbb5435ec"] 
[INFO   ] [2020-07-20 15:17:26.496234233] process done ExitSuccess
| [2020-07-20 15:17:26.496331173] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:26.498656826] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.500412517] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","git-annex"] 
[INFO   ] [2020-07-20 15:17:26.503977064] process done ExitSuccess
| [2020-07-20 15:17:26.504121615] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:26.506520913] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.506699248] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..783786ed8b606bc2a8cd8d9538988558228d62da","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:26.510785271] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.510903114] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","refs/heads/git-annex..7bac5ed757b26e16b5d18d4b30679fb91d48af87","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:26.515290814] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.515601717] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch"] 
[INFO   ] [2020-07-20 15:17:26.516536081] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","cat-file","--batch-check=%(objectname) %(objecttype) %(objectsize)"] 
[INFO   ] [2020-07-20 15:17:26.519158052] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","hash-object","-w","--stdin-paths","--no-filters"] 
[INFO   ] [2020-07-20 15:17:26.519821398] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:26.520527669] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","diff-index","--raw","-z","-r","--no-renames","-l0","--cached","7bac5ed757b26e16b5d18d4b30679fb91d48af87","--"] 
[INFO   ] [2020-07-20 15:17:26.525145402] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.526012243] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.526506888] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","log","7bac5ed757b26e16b5d18d4b30679fb91d48af87..refs/heads/git-annex","--pretty=%H","-n1"] 
[INFO   ] [2020-07-20 15:17:26.530345058] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.530549296] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:26.535657444] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.53580151] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","08dc7f5ef1120e8259be0a35f7675e418bd56a14","--no-gpg-sign","-p","refs/heads/git-annex","-p","7bac5ed757b26e16b5d18d4b30679fb91d48af87"] 
[INFO   ] [2020-07-20 15:17:26.540176551] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.540322003] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","02157d5baa9ce12023890023945431f4886f5688"] 
[INFO   ] [2020-07-20 15:17:26.544351238] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.546026937] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","annex.version","5"] 
[INFO   ] [2020-07-20 15:17:26.549800594] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.549930383] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:26.553011648] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.553182471] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:26.556982888] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.557112697] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:26.560205142] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.560349384] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","symbolic-ref","-q","HEAD"] 
[INFO   ] [2020-07-20 15:17:26.564321071] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.564496731] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/master"] 
[INFO   ] [2020-07-20 15:17:26.567532321] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.56762852] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","checkout","-q","-B","master"] 
[INFO   ] [2020-07-20 15:17:26.573122662] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.574690036] read: uname ["-n"] 
[INFO   ] [2020-07-20 15:17:26.577029004] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.57890157] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:26.581667566] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.581874399] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","config","remote.origin.annex-uuid","76c7b3df-f343-42a1-8c2e-68d2b44a6af4"] 
[INFO   ] [2020-07-20 15:17:26.585637183] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.585752595] read: git ["config","--null","--list"] 
[INFO   ] [2020-07-20 15:17:26.589160444] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.589832042] feed: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-index","-z","--index-info"] 
[INFO   ] [2020-07-20 15:17:26.593377952] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.593507853] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","show-ref","--hash","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:26.597258843] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.597458569] read: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","write-tree"] 
[INFO   ] [2020-07-20 15:17:26.601165258] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.601299873] chat: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","commit-tree","5f8a04b5ef2cc4a92272b81c6069219517b5d52e","--no-gpg-sign","-p","refs/heads/git-annex"] 
[INFO   ] [2020-07-20 15:17:26.604943442] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.605075791] call: git ["--git-dir=.git","--work-tree=.","--literal-pathspecs","-c","annex.dotfiles=true","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","-c","annex.dotfiles=true","-c","annex.retry=3","update-ref","refs/heads/git-annex","17032f4f4f53a743e68a04893160b9db7bb8ea5e"] 
[INFO   ] [2020-07-20 15:17:26.608690462] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.610449078] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.610861494] process done ExitSuccess 
[INFO   ] [2020-07-20 15:17:26.611205544] process done ExitSuccess 
[DEBUG  ] Process 1594497 exited with return code 0 
[Level 8] Finished running ['git-annex', 'init', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--debug'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'cat-file', 'blob', 'git-annex:remote.log'] 
[Level 5] CommandError: 'git cat-file blob git-annex:remote.log' failed with exitcode 128 under /tmp/datalad_temp_test_basics86fgkmko/subds2 [err: 'fatal: Not a valid object name git-annex:remote.log'] 
[Level 5] Detected file ri 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics5vtpotse/subds2 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-url-schemes', 'http https file'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] 
[Level 8] Finished running ['git', 'config', '--local', '--add', 'annex.security.allowed-http-addresses', 'all'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics5vtpotse/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[DEBUG  ] Update cloned subdataset /tmp/datalad_temp_test_basics86fgkmko/subds2 in parent 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', 'master^{commit}', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', 'master^{commit}', '--'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'submodule', 'update', '--checkout', '--init', '--', 'subds2'] 
[Level 8] Finished running ['git', 'submodule', 'update', '--checkout', '--init', '--', 'subds2'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] Installed subdataset in order to get /tmp/datalad_temp_test_basics86fgkmko/subds2 [install(/tmp/datalad_temp_test_basics86fgkmko/subds2)] 
[DEBUG  ] Result {'action': 'install', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'type': 'dataset', 'status': 'ok', 'source': {'source': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'version': None, 'type': 'giturl', 'giturl': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'default_destpath': 'subds2'}, 'message': ('Installed subdataset in order to get %s', '/tmp/datalad_temp_test_basics86fgkmko/subds2'), 'contains': [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds2')]} matches hook alwaysbids 
[DEBUG  ] Running hook alwaysbids: run_procedure{'dataset': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'spec': 'cfg_metadatatypes bids'} 
[Level 2] Entered eval_func for <function RunProcedure.__call__ at 0x7fa004ac2f70> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.interface.run_procedure.RunProcedure'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.interface.run_procedure.RunProcedure'> 
[DEBUG  ] Resolved dataset for run a procedure: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/.config/datalad/procedures' 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/etc/xdg/datalad/procedures' 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/procedures' 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds2) 
[DEBUG  ] Looking for procedure 'cfg_metadatatypes' in '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures' 
[INFO   ] Running procedure cfg_metadatatypes 
[DEBUG  ] Full procedure command: '/usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds2 bids' 
[Level 2] Entered eval_func for <function Run.__call__ at 0x7fa004ab0940> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.run.Run'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning generator_func from eval_func for <class 'datalad.core.local.run.Run'> 
[DEBUG  ] Resolved dataset for tracking outcomes of a command: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] tracking command output underneath Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds2) 
[DEBUG  ] chdir '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build' -> '/tmp/datalad_temp_test_basics86fgkmko/subds2'  
[DEBUG  ] chdir '/tmp/datalad_temp_test_basics86fgkmko/subds2' -> '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build' (coming back) 
[INFO   ] == Command start (output follows) ===== 
[Level 5] Running: /usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds2 bids 
[Level 5] Instantiating ssh manager 
[Level 5] Done importing main __init__ 
[Level 5] Importing support.network 
[Level 5] Done importing support.network 
[Level 5] Requested to provide version for cmd:git 
[DEBUG  ] parseParameters: Given "exclude_special_remotes: bool, optional
|   if True, don't return annex special remotes", we split into [('exclude_special_remotes', "exclude_special_remotes: bool, optional\n  if True, don't return annex special remotes")] 
[DEBUG  ] parseParameters: Given "with_urls_only : bool, optional
|   return only remotes which have urls", we split into [('with_urls_only', 'with_urls_only : bool, optional\n  return only remotes which have urls')] 
[Level 5] Importing dataset 
[Level 5] Done importing dataset 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics86fgkmko/subds2 into fields {'path': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[DEBUG  ] Resolved dataset for configuration: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 5] Detected <class 'datalad.support.annexrepo.AnnexRepo'> at /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 5] Running: ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Found 0 previous connections 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Parsed ri /tmp/datalad_temp_test_basics5vtpotse/subds2 into fields {'path': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'scheme': '', 'username': '', 'password': '', 'hostname': '', 'port': '', 'query': '', 'fragment': ''} 
[Level 5] Detected file ri 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config'] with status 0 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 5] Running: ['git', 'config', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config', '--add', 'datalad.metadata.nativetype', 'bids'] 
[Level 8] Finished running ['git', 'config', '--file', '/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config', '--add', 'datalad.metadata.nativetype', 'bids'] with status 0 
[Level 5] Importing datalad.interface.results 
[Level 5] Done importing datalad.interface.results 
[DEBUG  ] Discovering plugins 
[Level 5] Importing module datalad.core.local.save  
[DEBUG  ] Building doc for <class 'datalad.core.local.status.Status'> 
[DEBUG  ] Building doc for <class 'datalad.core.local.save.Save'> 
[DEBUG  ] Found matching interface ('datalad.core.local.save', 'Save', 'save') for save 
[Level 2] Entered eval_func for <function Save.__call__ at 0x7fbdecc09ca0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.save.Save'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.save.Save'> 
[DEBUG  ] Resolved dataset for saving: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[Level 2] Entered eval_func for <function Status.__call__ at 0x7fbdecc09f70> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.core.local.status.Status'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.core.local.status.Status'> 
[DEBUG  ] Resolved dataset for status reporting: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] query AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2).diffstatus() for paths: [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds2/.datalad/config')] 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o', '--', '.datalad/config'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-files', '--stage', '-z', '-d', '-m', '--exclude-standard', '-o'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2).get_content_info(...) 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-files', '-z', '-m', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-files', '-z', '-m', '--', '.datalad/config'] with status 0 
[DEBUG  ] AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2).get_content_info(...) 
[DEBUG  ] Query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', '.datalad/config'] 
[Level 8] Finished running ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l', '--', '.datalad/config'] with status 0 
[DEBUG  ] Done query repo: ['git', 'ls-tree', 'HEAD', '-z', '-r', '--full-tree', '-l'] 
[DEBUG  ] Done AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2).get_content_info(...) 
[DEBUG  ] Determined 1 datasets for saving from input arguments 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Running: ['git', 'diff', '--name-only', '--staged'] 
[Level 8] Finished running ['git', 'diff', '--name-only', '--staged'] with status 0 
[DEBUG  ] 1 path(s) to add to AnnexRepo(/tmp/datalad_temp_test_basics86fgkmko/subds2) {'.datalad/config': {'state': 'modified', 'type': 'file', 'gitshasum': '6e589f2293407f655afa0473ae5c8eaa6761bae4', 'prev_gitshasum': '6e589f2293407f655afa0473ae5c8eaa6761bae4'}} 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Running: ['git', 'annex', 'version', '--raw'] 
[Level 8] Finished running ['git', 'annex', 'version', '--raw'] with status 0 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.datalad/config'] 
[Level 3] Reading line from stdout 
[Level 3] Reading line from stdout 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 3] Processing provided line 
[Level 8] Finished running ['git-annex', 'add', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--include-dotfiles', '--debug', '--', '.datalad/config'] with status 0 
[DEBUG  ] Committing via direct call of git: ['git', 'commit', '-m', 'Configure metadata type(s)'] 
[DEBUG  ] Async run ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] 
[DEBUG  ] Launching process ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] 
[DEBUG  ] Process 1595564 started 
[DEBUG  ] Waiting for process 1595564 to complete 
[Level 5] Read 77 bytes from 1595564[stdout] 
[DEBUG  ] Process 1595564 exited with return code 0 
[Level 8] Finished running ['git', 'commit', '-m', 'Configure metadata type(s)', '--'] with status 0 
[Level 5] Running: ['git', 'symbolic-ref', 'HEAD'] 
[Level 8] Finished running ['git', 'symbolic-ref', 'HEAD'] with status 0 
[DEBUG  ] No sync necessary, no corresponding branch detected 
[Level 5] Running: ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] 
[Level 8] Finished running ['git', 'show', '-z', '--no-patch', '--format=%H', '--'] with status 0 
[Level 5] Exiting 
[Level 8] Finished running '/usr/bin/python3.8 /build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/datalad/resources/procedures/cfg_metadatatypes.py /tmp/datalad_temp_test_basics86fgkmko/subds2 bids' with status 0 
[INFO   ] == Command exit (modification check follows) ===== 
[DEBUG  ] Result {'action': 'install', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'type': 'dataset', 'status': 'ok', 'source': {'source': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'version': None, 'type': 'giturl', 'giturl': '/tmp/datalad_temp_test_basics5vtpotse/subds2', 'default_destpath': 'subds2'}, 'message': ('Installed subdataset in order to get %s', '/tmp/datalad_temp_test_basics86fgkmko/subds2'), 'contains': [PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds2')]} matches hook wtf 
[DEBUG  ] Running hook wtf: wtf{'result_renderer': 'disabled'} 
[Level 2] Entered eval_func for <function WTF.__call__ at 0x7fa004b418b0> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.plugin.wtf.WTF'> 
[Level 2] Returning return_func from eval_func for <class 'datalad.plugin.wtf.WTF'> 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Requested to provide version for cmd:git 
[Level 5] Requested to provide version for cmd:bundled-git 
[Level 5] Requested to provide version for cmd:system-git 
[Level 5] Requested to provide version for cmd:system-ssh 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for annexremote 
[Level 5] Requested to provide version for appdirs 
[Level 5] Requested to provide version for boto 
[DEBUG  ] Module boto seems to be not present 
[Level 5] Requested to provide version for exifread 
[Level 5] Requested to provide version for git 
[Level 5] Requested to provide version for gitdb 
[Level 5] Requested to provide version for humanize 
[Level 5] Requested to provide version for iso8601 
[Level 5] Requested to provide version for keyring 
[Level 5] Requested to provide version for keyrings.alt 
[Level 5] Requested to provide version for msgpack 
[Level 5] Requested to provide version for mutagen 
[Level 5] Requested to provide version for patool 
[DEBUG  ] Module patool seems to be not present 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for requests 
[Level 5] Requested to provide version for scrapy 
[DEBUG  ] Module scrapy seems to be not present 
[Level 5] Requested to provide version for wrapt 
[Level 5] Requested to provide version for cmd:git 
[Level 5] Requested to provide version for tqdm 
[Level 5] Requested to provide version for cmd:7z 
[Level 5] Requested to provide version for patoolib 
[Level 5] Requested to provide version for cmd:system-git 
[Level 5] Requested to provide version for cmd:annex 
[Level 5] Requested to provide version for cmd:bundled-git 
[Level 5] Requested to provide version for cmd:system-ssh 
[Level 5] Requested to provide version for annexremote 
[Level 5] Requested to provide version for appdirs 
[Level 5] Requested to provide version for exifread 
[Level 5] Requested to provide version for git 
[Level 5] Requested to provide version for gitdb 
[Level 5] Requested to provide version for humanize 
[Level 5] Requested to provide version for iso8601 
[Level 5] Requested to provide version for keyring 
[Level 5] Requested to provide version for keyrings.alt 
[Level 5] Requested to provide version for msgpack 
[Level 5] Requested to provide version for mutagen 
[Level 5] Requested to provide version for requests 
[Level 5] Requested to provide version for wrapt 
[Level 5] Running: ['git', 'annex', 'version'] 
[Level 8] Finished running ['git', 'annex', 'version'] with status 0 
[DEBUG  ] Failed to create sample file for length 314. Last succeeded was 313. Exception: [Errno 36] File name too long: '/build/datalad-0.13.1/.pybuild/cpython3_3.8_datalad/build/dl35695_________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________' [wtf.py:get_max_path_length:72] 
[Level 2] Entered eval_func for <function Subdatasets.__call__ at 0x7fa004c11e50> 
[DEBUG  ] Determined class of decorated function: <class 'datalad.local.subdatasets.Subdatasets'> 
[Level 5] Running: ['git', 'config', '-z', '-l', '--show-origin'] 
[Level 8] Finished running ['git', 'config', '-z', '-l', '--show-origin'] with status 0 
[Level 2] Returning return_func from eval_func for <class 'datalad.local.subdatasets.Subdatasets'> 
[DEBUG  ] Resolved dataset for subdataset reporting/modification: /tmp/datalad_temp_test_basics86fgkmko/subds2 
[DEBUG  ] Query subdatasets of Dataset(/tmp/datalad_temp_test_basics86fgkmko/subds2) 
[DEBUG  ] Not reporting result (excluded by filter <function get_result_filter.<locals>._fx at 0x7fa0020c3280> with arguments {'path': None, 'dataset': Dataset('/tmp/datalad_temp_test_basics86fgkmko/subds2'), 'fulfilled': None, 'recursive': False, 'recursion_limit': None, 'contains': PosixPath('/tmp/datalad_temp_test_basics86fgkmko/subds2'), 'bottomup': False, 'set_property': None, 'delete_property': None, 'on_failure': 'ignore', 'result_filter': <function is_ok_dataset at 0x7fa004c5a820>} [utils.py:keep_result:655]): {'action': 'subdataset', 'path': '/tmp/datalad_temp_test_basics86fgkmko/subds2', 'status': 'impossible', 'message': 'path not contained in any matching subdataset'} 
[DEBUG  ] Determine what files match the query to work with 
[DEBUG  ] Process file list chunk 0 (length 1) 
[Level 5] Running: ['git', '-c', 'annex.merge-annex-branches=false', 'annex', 'find', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--not', '--in', '.', '--debug', '--', '.'] 
[Level 8] Finished running ['git', '-c', 'annex.merge-annex-branches=false', 'annex', 'find', '-c', 'annex.dotfiles=true', '-c', 'annex.retry=3', '--json', '--json-error-messages', '--not', '--in', '.', '--debug', '--', '.'] with status 0 
[DEBUG  ] No files found needing fetching. 
[INFO   ] Keeping temp file: /tmp/datalad_temp_test_basics86fgkmko 
[INFO   ] Keeping temp file: /tmp/datalad_temp_test_basics5vtpotse 
> /usr/lib/python3/dist-packages/nose/tools/trivial.py(29)eq_()
-> raise AssertionError(msg or "%r != %r" % (a, b))

@yarikoptic
Copy link
Member Author

arrived to the same bug while trying to build 0.13.5 on stock debian sid. Sure thing, like a good bug, doesn't appear whenever I try to run manually as

root@smaug:/tmp/buildd/datalad-0.13.5# PYTHONPATH=$PWD python3 -m nose -s -v /build/datalad-0.13.5/.pybuild/cpython3_3.9_datalad/build/datalad/core/local/tests/test_resulthooks.py
datalad.core.local.tests.test_resulthooks.test_basics ... ok
Versions: annexremote=1.4.3 appdirs=1.4.4 cmd:7z=16.02 cmd:annex=8.20201103 cmd:bundled-git=UNKNOWN cmd:git=2.29.2 cmd:system-git=2.29.2 cmd:system-ssh=8.4p1 exifread=2.3.2 humanize=0.0.0 iso8601=0.1.12 keyring=21.5.0 keyrings.alt=4.0.1 msgpack=1.0.0 mutagen=1.45.1 requests=2.24.0 tqdm=4.51.0 wrapt=1.12.1
Obscure filename: str=b' |;&%b5{}\'" .datc ' repr=' |;&%b5{}\'" .datc '
Encodings: default='utf-8' filesystem='utf-8' locale.prefered='UTF-8'
Environment: PYTHONPATH='/tmp/buildd/datalad-0.13.5' LANG='C' LC_ALL='C' PATH='/usr/lib/ccache:/usr/sbin:/usr/bin:/sbin:/bin' GIT_CONFIG_PARAMETERS="'init.defaultBranch=dl-test-branch'"

----------------------------------------------------------------------
Ran 1 test in 8.277s

OK

probably will just skip that test_resulthooks.... but - surprise, trying to specify the entire test file via -e seems to make that bug reliable:

root@smaug:/tmp/buildd/datalad-0.13.5# PYTHONPATH=$PWD python3 -m nose -s -v -e test_resulthooks /build/datalad-0.13.5/.pybuild/cpython3_3.9_datalad/build/datalad/core/local/tests/test_resulthooks.py
datalad.core.local.tests.test_resulthooks.test_basics ... FAIL
Versions: annexremote=1.4.3 appdirs=1.4.4 cmd:7z=16.02 cmd:annex=8.20201103 cmd:bundled-git=UNKNOWN cmd:git=2.29.2 cmd:system-git=2.29.2 cmd:system-ssh=8.4p1 exifread=2.3.2 humanize=0.0.0 iso8601=0.1.12 keyring=21.5.0 keyrings.alt=4.0.1 msgpack=1.0.0 mutagen=1.45.1 requests=2.24.0 tqdm=4.51.0 wrapt=1.12.1
Obscure filename: str=b' |;&%b5{}\'" .datc ' repr=' |;&%b5{}\'" .datc '
Encodings: default='utf-8' filesystem='utf-8' locale.prefered='UTF-8'
Environment: PYTHONPATH='/tmp/buildd/datalad-0.13.5' LANG='C' LC_ALL='C' PATH='/usr/lib/ccache:/usr/sbin:/usr/bin:/sbin:/bin' GIT_CONFIG_PARAMETERS="'init.defaultBranch=dl-test-branch'"

======================================================================
FAIL: datalad.core.local.tests.test_resulthooks.test_basics
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/build/datalad-0.13.5/.pybuild/cpython3_3.9_datalad/build/datalad/tests/utils.py", line 745, in _wrap_with_tempfile
    return t(*(arg + (filename,)), **kw)
  File "/build/datalad-0.13.5/.pybuild/cpython3_3.9_datalad/build/datalad/tests/utils.py", line 745, in _wrap_with_tempfile
    return t(*(arg + (filename,)), **kw)
  File "/build/datalad-0.13.5/.pybuild/cpython3_3.9_datalad/build/datalad/core/local/tests/test_resulthooks.py", line 100, in test_basics
    eq_(clone_sub2.config.get('datalad.metadata.nativetype'), 'bids')
AssertionError: None != 'bids'
-------------------- >> begin captured logging << --------------------
datalad.utils: Level 5: Importing datalad.utils
datalad.utils: DEBUG: Maximal length of cmdline string (adjusted for safety margin): 1048576
datalad.utils: Level 5: Done importing datalad.utils
datalad.cmd: Level 9: Will use git under '' (no adjustments to PATH if empty string)
datalad.cmd: Level 5: Running: ['git', 'version']
datalad.cmd: Level 8: Finished running ['git', 'version'] with status 0
datalad.cmd: Level 5: Running: ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin']
datalad.cmd: Level 8: Finished running ['git', '--git-dir=', 'config', '-z', '-l', '--show-origin'] with status 0
datalad.config: WARNING: It is highly recommended to configure Git before using DataLad. Set both 'user.name' and 'user.email' configuration variables.
datalad.config: WARNING: It is highly recommended to configure Git before using DataLad. Set both 'user.name' and 'user.email' configuration variables.
datalad.ui: Level 5: Starting importing ui
datalad.ui.dialog: Level 5: Starting importing ui.dialog
datalad.ui.dialog: Level 5: Done importing ui.dialog
datalad.ui: Level 5: Initiating UI switcher
datalad.ui: DEBUG: UI set to DialogUI(out=<TextIOWrapper>)
datalad.ui: Level 5: Done importing ui
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
keyring.backend: DEBUG: Loading KWallet
keyring.backend: DEBUG: Loading SecretService
keyring.backend: DEBUG: Loading Windows
keyring.backend: DEBUG: Loading chainer
keyring.backend: DEBUG: Loading macOS
keyring.backend: DEBUG: Loading Gnome
keyring.backend: DEBUG: Loading Google
keyring.backend: DEBUG: Loading Windows (alt)
keyring.backend: DEBUG: Loading file
keyring.backend: DEBUG: Loading keyczar
keyring.backend: DEBUG: Loading multi
keyring.backend: DEBUG: Loading pyfs
asyncio: DEBUG: Using selector: EpollSelector
asyncio: DEBUG: Using selector: EpollSelector
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 1 test in 7.007s

FAILED (failures=1)

so the quick way would sacrifice also one in test_run

$> git grep test_basics
datalad/core/local/tests/test_resulthooks.py:def test_basics(src, dst):
datalad/core/local/tests/test_run.py:def test_basics(path, nodspath):
datalad/interface/tests/test_run_procedure.py:    # set up dataset with registered procedure (c&p from test_basics):
datalad/interface/tests/test_run_procedure.py:    # set up dataset with registered procedure (c&p from test_basics):

NB a potential fix AFAIK in #4364 was not favored and thus was close without merge

yarikoptic added a commit that referenced this issue Nov 24, 2020
@yarikoptic
Skip test_basics as a quick workaround fro
002ebb3 
#4753
@kyleam
Copy link
Contributor

kyleam commented Jan 11, 2021

It seems likely that this was addressed by some combination of gh-5275 and gh-5276.

@kyleam kyleam added possibly-fixed spurious-test-failure Tests that fail unreliably labels Jan 11, 2021
@adswa
Copy link
Member

adswa commented Jul 26, 2021

I see that the skipped test from 002ebb3 is still skipped... Given that Kyle reported that the problem was likely fixed, shall we try to revert that commit and see what happens? I don't know how the Debian builds work, though, would a PR against this branch trigger a unit test battery for what is specified in the 'rules' file?

@yarikoptic
Copy link
Member Author

sorry, didn't update here yet (still building 18.04 after some dances). pushed debian branch and tag now. I have disabled tests skipping, and 0.14.6 built fine on 20.04. Confirming :

neurodebian@smaug ~/deb/builds/datalad/0.14.6-1 % grep 20.04 summary.build 
datalad_0.14.6-1~nd20.04+1_amd64.build	OK	50:04.09 real, 1893.18 user, 1369.88 sys, 3466672 out
neurodebian@smaug ~/deb/builds/datalad/0.14.6-1 % grep test_basic datalad_0.14.6-1~nd20.04+1_amd64.build
datalad.core.local.tests.test_resulthooks.test_basics ... ok
datalad.core.local.tests.test_run.test_basics ... /bin/sh: 1: 7i3amhmuch9invalid: not found
datalad.customremotes.tests.test_archives.test_basic_scenario ... ok
datalad.customremotes.tests.test_datalad.test_basic_scenario_s3 ... SKIP: Skipping since no network settings
datalad.customremotes.tests.test_datalad.test_basic_scenario_local_url ... .: store(-) [/tmp/datalad_temp_test_nested_pushclone_cycle_allplatformsxpip3uxk/b56/7699a-69d6-4876-9836-0efa18be1fea (git)]
datalad.metadata.tests.test_aggregation.test_basic_aggregate ... ok
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/dataset_description.json /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/dataset_description.json
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/dataset_description.json /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/dataset_description.json
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/subsub /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/subsub
/tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/subsub/dataset_description.json /tmp/datalad_temp_tree_test_basic_aggregatebaumwz9n/origin/sub/subsub/dataset_description.json
datalad.tests.test_api.test_basic_setup ... ok
datalad.tests.test_dochelpers.test_basic ... ok

so I guess we can let this issue RiP

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
severity-important major effect on the usability of a package, without rendering it completely unusable to everyone spurious-test-failure Tests that fail unreliably
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@yarikoptic @kyleam @adswa