Validation failing for most recent 0.67.3 release on assets not listed

[aaronkanzer]

This error was observed by @ayendiki when uploading data to LINC Archive on version 0.67.3 (all issues were resolved once downgrading to 0.67.0) -- both commands failed at 0.67.3:

dandi upload -i linc 000003/derivatives/histology/sub-MF278/sub-MF278_stacked_blockface_masked_grayscale_level4.nii.gz

and

DANDI_DEVEL=1 dandi upload -i linc --validation skip 000003/derivatives/histology/sub-MF278/sub-MF278_stacked_blockface_masked_grayscale_level4.nii.gz

Investigating now -- but the errors that came about signaled that BIDS validation was occuring on all files in the directory, even though upload was centered purely on 000003/derivatives/histology/sub-MF278/sub-MF278_stacked_blockface_masked_grayscale_level4.nii.gz with a error shown down below:

$ dandi upload -i linc 000003/derivatives/histology/sub-MF278/sub-MF278_stacked_blockface_masked_grayscale_level4.nii.gz
2025-04-14 15:19:54,352 [    INFO] Found 2 files to consider
$<2>PATH$<2> $<2>$<2>PATH$<2>                                                                                       $<2>SIZE$<2>    $<2>ERRORS$<2> $<2>PROGRESS$<2> $<2>STATUS$<2> $<2>MESSAGE$$<2>$<2>PATH$<2>                                                                                       $<2>SIZE$<2>    $<2>ERRORS$<2> $<2>PROGRESS$<2> $<2>STATUS$<2>    $<2>M$<2>$<2>PATH$<2>                                                                                       $<2>SIZE$<2>    $<2>ERRORS$<2> $<2>PROGRESS$<2> $<2>STATUS$<2>           $<2>MESSAGE$<2>                                                                     1.6 kB                  skipped   should be edited online
$<2>$<2>dandiset.yaml$<2>                                                                              1.6 kB                  skipped          should be edited online
$<2>$<2>derivatives/histology/sub-MF278/sub-MF278_stacked_blockface_masked_grayscale_level4.nii.gz$<2> 4.9 MB                  pre-validating
Summary:                                                                                   4.9 MB                  1 skipped        1 should be edited online
                                                                                                                   1 pre-validating
--- Logging error ---
Traceback (most recent call last):
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 703, in format
    record.message = record.getMessage()
                     ^^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 392, in getMessage
    msg = msg % self.args
          ~~~~^~~~~~~~~~~
ValueError: unsupported format character '`' (0x60) at index 25
Call stack:
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/threading.py", line 1032, in _bootstrap
    self._bootstrap_inner()
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/concurrent/futures/thread.py", line 92, in _worker
    work_item.run()
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/pyout/interface.py", line 482, in async_fn
    for i in gen:
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/upload.py", line 264, in process_path
    validation_statuses = dfile.get_validation_errors()
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/files/bids.py", line 285, in get_validation_errors
    return GenericAsset.get_validation_errors(
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/files/bases.py", line 185, in get_validation_errors
    asset = self.get_metadata(digest=self._DUMMY_DIGEST)
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/files/bids.py", line 199, in get_metadata
    metadata = self.bids_dataset_description.get_asset_metadata(self)
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/files/bids.py", line 128, in get_asset_metadata
    self._validate()
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/files/bids.py", line 90, in _validate
    results = validate_bids(self.bids_root)
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/dandi/validate.py", line 47, in validate_bids
    validation_result = validate_bids_(paths, exclude_files=["dandiset.yaml"])
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/bidsschematools/validator.py", line 644, in validate_bids
    validation_result = validate_all(
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/bidsschematools/validator.py", line 432, in validate_all
    lgr.debug("\t* `%s`, with pattern: `%`", target_path, target_regex)
Message: '\t* `%s`, with pattern: `%`'
Arguments: ('/autofs/space/aspasia_002/users/linc/000003/participants.tsv', '(?:.*/)?(?P<path>dataset_description\\.json)(?:/.*)?\\Z')
--- Logging error ---
Traceback (most recent call last):
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 703, in format
    record.message = record.getMessage()
                     ^^^^^^^^^^^^^^^^^^^
  File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/logging/__init__.py", line 392, in getMessage
    msg = msg % self.args

[aaronkanzer]

Cc @candleindark @yarikoptic @satra @kabilar @jwodder

[aaronkanzer]

Tagging #1591 as it may be a source of error -- looking closer....

[yarikoptic]

It is a bug in logging in bidsschematools - missing s for the second %

File "/autofs/space/aspasia_002/users/code/miniforge3/envs/dandi/lib/python3.12/site-packages/bidsschematools/validator.py", line 432, in validate_all
    lgr.debug("\t* `%s`, with pattern: `%`", target_path, target_regex)

I thought i submitted a fix but I fail to find it so likely I didn't.

But also the question if we should reduce logging to INFO there by default

[yarikoptic]

Submitted

• Fix log line %interpolation in validator.py bids-standard/bids-specification#2102
  while on the phone... Please try out if you can @aaronkanzer happen there is more such bugs there

[candleindark]

But also the question if we should reduce logging to INFO there by default

I think, in general, the default log level should be INFO. The DEBUG log level is for debugging purposes. The DEBUG log level produces too much information for regular use, and I think a point to have a DEBUG level is to have a level to put verbose info without cluttering the log in regular use.

[yarikoptic]

Yes, BUT we log into a file at debug level iirc and it already came handy to be able to introspect what went wrong since in many use cases (connections etc), it is impossible to reproduce

[yarikoptic]

The question here is how to work around. If log filtering is done before formatting - then we could filter that log on current versions of bidsschematools

[yarikoptic]

Or just raise to INFO for bidsschematools only for now

[candleindark]

Yes, BUT we log into a file at debug level iirc and it already came handy to be able to introspect what went wrong since in many use cases (connections etc), it is impossible to reproduce

I think that if that information is essential, not just for debugging purpose, then it should be logged lgr.info or above.

[yarikoptic]

it is potentially essential for debugging, thus at debug level logged into a file which is IMHO appropriate level. bidsschematools got a fix and hopefully would get released soon. It might be interesting to understand why it surfaced just now, but not critical. @aaronkanzer would you have a chance to try with fixed up bidsschematools?

[yarikoptic]

presumably addressed since didn't hear from @aaronkanzer after my last comment to him

[yarikoptic-gitmate]

The root cause was a logging format string bug in bidsschematools, fixed upstream in bids-standard/bids-specification#2102. Can be closed if the upstream fix has been released.

[aaronkanzer]

presumably addressed since didn't hear from @aaronkanzer after my last comment to him

Hi @yarikoptic! Just saw your notification -- greetings from down under in Australia, hope all is well :)