BUG:--- Logging error --- #509

fMizki · 2022-05-18T07:17:40Z

Hi,

I got un error I couldn't understand.
On the file I attached, I copied the errors.
The errors '1:' and '3:' in the file are what I got when I ran vak prep and predict though I didn't get it when I ran on the other files of which parameters are completely the same with those I put when I got the error. Only the difference is the predicting files, so it is possible that some of them are broken.
And when did vak prep and predict with the completely same files with '1:' again( I just commanded samely without changes in any files), I got the error '2:'.
logging_error.txt

I'm sorry if it were a problem on my computer or my files.

The text was updated successfully, but these errors were encountered:

NickleDave · 2022-05-18T16:36:15Z

Hi @fMizki -- I'm sorry you're running into this issue.
Thank you for letting us know and for providing the detailed bug report.

I can see the crash occurred after the script had been running for a while, I'm sure that must be frustrating.

I also know that the error messages that we get from dask are not particularly helpful and kind of cryptic.

There are a couple of things I can think of that might explain these errors but I'm not sure how to narrow them down.

Can you please do the following?

reply with your .toml config files. Please make sure they include the csv_path option that was added by vak when it ran prep (or if that was not added, it would be good to know)
can you try running the exact commands one more time on the "bad" directory just to verify the error is at least reproducible?

Let's try that first and then we can take it from there

NickleDave · 2022-05-18T16:36:54Z

Replying with some thoughts

Possible explanations:

There's some issue with logging itself -- that's what the language about logging in the traceback might make one think at first
There's some issue with paths? I'm leaning towards this because of Errno 22 and Errno 2 that both have to do with path / file not found-type errors (see for example https://stackoverflow.com/questions/25584124/oserror-errno-22-invalid-argument-when-use-open-in-python but note that you can't "fix" these errors e.g. by adding r"path/to/thing" in a .toml file since .toml is not Python--it might be some fix we need to make in vak with how we "build" paths)
There's some error with your files as you said. I can't rule that out but the fact that prep completes in some cases makes me think it's not that, not sure though

fMizki · 2022-05-19T06:35:35Z

Thank you for your reply.

reply with your .toml config files. Please make sure they include the csv_path option that was added by vak when it ran prep (or if that was not added, it would be good to know)

cyn191_predict11.zip

Well, when I failed in prep and got the error '1:' in the .txt file, csv_path had not added, but when I redid the command and stopped in predict shown in '2:' in the .txt file, csv_path was added.

can you try running the exact commands one more time on the "bad" directory just to verify the error is at least reproducible?

When I ran just 'vak predict' as vak prep had scceeded with logging error('2:' in the file), I got the below, but somehow prediction results are correct( same with the '3:' in the .txt file)

(vak-env-cuda113) Z:\cyn191>vak predict manual/211225-220204/cyn191_predict11.toml
Logging results to manual\211225-220204\output\prep
loading SpectScaler from path: manual\train\results\results_220515_113717\StandardizeSpect
loading labelmap from path: manual\train\results\results_220515_113717\labelmap.json
loading dataset to predict from csv path: manual\211225-220204\output\prep\predict_data11_prep_220518_071706.csv
will save annotations in .csv file: manual\211225-220204\output\cyn191_predict11.annot.csv
dataset has timebins with duration: 0.00145
shape of input to networks used for predictions: torch.Size([1, 1025, 176])
instantiating models from model-config map:/n{'TweetyNet': {'optimizer': {'lr': 0.001}, 'network': {}, 'loss': {}, 'metrics': {}}}
loading checkpoint for TweetyNet from path: manual\train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
Loading checkpoint from:
manual\train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
running predict method of TweetyNet
batch 4999 / 5000: 100%|█████████████████████████████████████████████████████████| 5000/5000 [1:26:22<00:00,  1.04s/it]
  0%|                                                                                         | 0/5000 [00:00<?, ?it/s]--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
    self.flush()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1084, in flush
    self.stream.flush()
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\predict.py", line 42, in predict
    core.predict(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\predict.py", line 233, in predict
    log_or_print(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'converting predictions to annotations'
Arguments: ()
converting predictions to annotations
100%|████████████████████████████████████████████████████████████████████████████| 5000/5000 [1:26:53<00:00,  1.04s/it]

fMizki · 2022-05-19T06:42:43Z

Replying with some thoughts

Possible explanations:

There's some issue with logging itself -- that's what the language about logging in the traceback might make one think at first

There's some issue with paths? I'm leaning towards this because of Errno 22 and Errno 2 that both have to do with path / file not found-type errors (see for example https://stackoverflow.com/questions/25584124/oserror-errno-22-invalid-argument-when-use-open-in-python but note that you can't "fix" these errors e.g. by adding r"path/to/thing" in a .toml file since .toml is not Python--it might be some fix we need to make in vak with how we "build" paths)

I'm sure all paths I had to tell to vak in the .toml file are correct.

There's some error with your files as you said. I can't rule that out but the fact that prep completes in some cases makes me think it's not that, not sure though

I agree.

Well, actually even though I'm on the more powerful machine, the time for the prep has not been reduced. This makes me think that there might be something to do with dask, but my parameters also can be the cause.

NickleDave · 2022-05-19T13:40:11Z

I'm sure all paths I had to tell to vak in the .toml file are correct.

Sorry, to be clear, what I mean is that there's an error causes by how the code in vak creates paths, not how you are writing paths.

But now that I think about it, that can't be the explanation, or you would get similar errors for other directories.
It's only happening sometimes.

When I ran just 'vak predict' as vak prep had scceeded with logging error('2:' in the file), I got the below, but somehow prediction results are correct( same with the '3:' in the .txt file)

Yes, I think there's multiple things interacting here and that's what's making it confusing.

What's particularly surprising is that the code continues execution after the logging-related errors.
That makes me think it's something low-level happening in dask, that we at least need to handle somehow so it doesn't confuse people.

This is the new environment you made where you installed pytorch before installing vak, right?
Could you please:

reply with the environment files as you did before here? BUG: CUDA capability sm_86 error with pytorch #508 (comment) (but for this new environment, assuming I'm right that's it's not the old one)
provide more detail about your operating system. Is it Windows 10? 11? Are you running in Anaconda terminal or Powershell or some other place?
if possible, share with me by email the data that's causing this crash, e.g. just the one directory of predict data and the directory "results_220515_11371". Please include both the train and predict toml files you are using

I would like to try and create your environment on my Windows machine and see if I can reproduce these errors.

NickleDave · 2022-05-19T13:46:02Z

I'm going to reply with the full tracebacks you attached above so it's more searchable.
I'll also comment on what I think is going on. A bit of thinking out loud, please forgive me

(vak-env-cuda113) Z:\cyn191>(vak prep manual/211225-220204/cyn191_predict11.toml   && vak predict manual/211225-220204/cyn191_predict11.toml )
determined that purpose of config file is: predict
will add 'csv_path' option to 'PREDICT' section
purpose for dataset: predict
will not split dataset
creating dataset from spectrogram files in: manual\211225-220204\predict_data11
validating set of spectrogram files
[########################################] | 100% Completed |  1hr 36min 34.7s
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
    self.flush()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1084, in flush
    self.stream.flush()
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\prep.py", line 132, in prep
    vak_df, csv_path = core.prep(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\prep.py", line 205, in prep
    vak_df = dataframe.from_files(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\dataframe.py", line 171, in from_files
    vak_df = spect.to_dataframe(**to_dataframe_kwargs, logger=logger)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 262, in to_dataframe
    log_or_print(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'creating pandas.DataFrame representing dataset from spectrogram files'
Arguments: ()
creating pandas.DataFrame representing dataset from spectrogram files
[                                        ] | 2% Completed | 53min 10.2s
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\prep.py", line 132, in prep
    vak_df, csv_path = core.prep(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\prep.py", line 205, in prep
    vak_df = dataframe.from_files(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\dataframe.py", line 171, in from_files
    vak_df = spect.to_dataframe(**to_dataframe_kwargs, logger=logger)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 268, in to_dataframe
    records = list(spect_path_annot_tuples.map(_to_record))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\bag\core.py", line 1471, in __iter__
    return iter(self.compute())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\base.py", line 292, in compute
    (result,) = compute(self, traverse=False, **kwargs)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\base.py", line 575, in compute
    results = schedule(dsk, keys, **kwargs)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\multiprocessing.py", line 220, in get
    result = get_async(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\local.py", line 508, in get_async
    raise_exception(exc, tb)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\multiprocessing.py", line 110, in reraise
    raise exc
dask.multiprocessing.OSError: [Errno 22] Invalid argument

Traceback
---------
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\local.py", line 221, in execute_task
    result = _execute_task(task, data)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\core.py", line 119, in _execute_task
    return func(*(_execute_task(a, cache) for a in args))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\bag\core.py", line 1845, in reify
    seq = list(seq)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\bag\core.py", line 2033, in __next__
    return self.f(*vals)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 226, in _to_record
    spect_dur = spect_dict[spect_key].shape[-1] * timebin_dur
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\npyio.py", line 243, in __getitem__
    return format.read_array(bytes,
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 778, in read_array
    data = _read_bytes(fp, read_size, "array data")
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 907, in _read_bytes
    r = fp.read(size - len(data))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 925, in read
    data = self._read1(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 995, in _read1
    data = self._read2(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 1025, in _read2
    data = self._fileobj.read(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 745, in read
    data = self._file.read(n)

This is the first error you report ("1:")

NickleDave · 2022-05-19T13:46:55Z

We can see in 1: that the error in the middle appears to be one of the mysterious logging tracebacks, that does not force the problem to halt execution:

File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'creating pandas.DataFrame representing dataset from spectrogram files'
Arguments: ()
[                                        ] | 2% Completed | 53min 10.2s

because it continued running after (for an hour before it crashed 🙁)

but the next error is definitely fatal.
I'm pretty sure it's some issue involved with trying to open an npz file that ultimately caused the crash

  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\base.py", line 292, in compute
    (result,) = compute(self, traverse=False, **kwargs)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\base.py", line 575, in compute
    results = schedule(dsk, keys, **kwargs)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\multiprocessing.py", line 220, in get
    result = get_async(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\local.py", line 508, in get_async
    raise_exception(exc, tb)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\multiprocessing.py", line 110, in reraise
    raise exc
dask.multiprocessing.OSError: [Errno 22] Invalid argument

Traceback
---------
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\local.py", line 221, in execute_task
    result = _execute_task(task, data)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\core.py", line 119, in _execute_task
    return func(*(_execute_task(a, cache) for a in args))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\bag\core.py", line 1845, in reify
    seq = list(seq)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\dask\bag\core.py", line 2033, in __next__
    return self.f(*vals)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 226, in _to_record
    spect_dur = spect_dict[spect_key].shape[-1] * timebin_dur
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\npyio.py", line 243, in __getitem__
    return format.read_array(bytes,
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 778, in read_array
    data = _read_bytes(fp, read_size, "array data")
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 907, in _read_bytes
    r = fp.read(size - len(data))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 925, in read
    data = self._read1(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 995, in _read1
    data = self._read2(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 1025, in _read2
    data = self._fileobj.read(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 745, in read
    data = self._file.read(n)

NickleDave · 2022-05-19T13:56:53Z

This is the second error you report ("2:")

(vak-env-cuda113) Z:\cyn191>(vak prep manual/211225-220204/cyn191_predict11.toml   && vak predict manual/211225-220204/cyn191_predict11.toml )
determined that purpose of config file is: predict
will add 'csv_path' option to 'PREDICT' section
purpose for dataset: predict
will not split dataset
creating dataset from spectrogram files in: manual\211225-220204\predict_data11
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
    self.flush()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1084, in flush
    self.stream.flush()
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\prep.py", line 132, in prep
    vak_df, csv_path = core.prep(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\prep.py", line 205, in prep
    vak_df = dataframe.from_files(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\dataframe.py", line 171, in from_files
    vak_df = spect.to_dataframe(**to_dataframe_kwargs, logger=logger)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 199, in to_dataframe
    files.spect.is_valid_set_of_spect_files(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\files\spect.py", line 193, in is_valid_set_of_spect_files
    log_or_print("validating set of spectrogram files", logger=logger, level="info")
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'validating set of spectrogram files'
Arguments: ()
validating set of spectrogram files
[########################################] | 100% Completed |  1hr 27min 34.9s
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
    self.flush()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1084, in flush
    self.stream.flush()
OSError: [Errno 22] Invalid argument
Call stack:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\prep.py", line 132, in prep
    vak_df, csv_path = core.prep(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\prep.py", line 205, in prep
    vak_df = dataframe.from_files(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\dataframe.py", line 171, in from_files
    vak_df = spect.to_dataframe(**to_dataframe_kwargs, logger=logger)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\io\spect.py", line 262, in to_dataframe
    log_or_print(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'creating pandas.DataFrame representing dataset from spectrogram files'
Arguments: ()
creating pandas.DataFrame representing dataset from spectrogram files
[########################################] | 100% Completed |  1hr  0min 52.2s
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
    self.flush()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1084, in flush
    self.stream.flush()
OSError: [Errno 22] Invalid argument
Call stack:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\prep.py", line 132, in prep
    vak_df, csv_path = core.prep(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\prep.py", line 241, in prep
    log_or_print(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'saving dataset as a .csv file: manual\\211225-220204\\output\\prep\\predict_data11_prep_220518_071706.csv'
Arguments: ()
saving dataset as a .csv file: manual\211225-220204\output\prep\predict_data11_prep_220518_071706.csv
Logging results to manual\211225-220204\output\prep
loading SpectScaler from path: manual\train\results\results_220515_113717\StandardizeSpect
loading labelmap from path: manual\train\results\results_220515_113717\labelmap.json
loading dataset to predict from csv path: manual\211225-220204\output\prep\predict_data11_prep_220518_071706.csv
will save annotations in .csv file: manual\211225-220204\output\cyn191_predict11.annot.csv
dataset has timebins with duration: 0.00145
shape of input to networks used for predictions: torch.Size([1, 1025, 176])
instantiating models from model-config map:/n{'TweetyNet': {'optimizer': {'lr': 0.001}, 'network': {}, 'loss': {}, 'metrics': {}}}
loading checkpoint for TweetyNet from path: manual\train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
Loading checkpoint from:
manual\train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
running predict method of TweetyNet
batch 4999 / 5000: 100%|█████████████████████████████████████████████████████████| 5000/5000 [1:17:54<00:00,  1.07it/s]
  0%|                                                                                         | 0/5000 [00:00<?, ?it/s]converting predictions to annotations
 80%|████████████████████████████████████████████████████████████▌               | 3983/5000 [1:45:54<27:02,  1.60s/it]
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\Scripts\vak-script.py", line 9, in <module>
    sys.exit(main())
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\__main__.py", line 45, in main
    cli.cli(command=args.command, config_file=args.configfile)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\cli.py", line 30, in cli
    COMMAND_FUNCTION_MAP[command](toml_path=config_file)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\cli\predict.py", line 42, in predict
    core.predict(
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\core\predict.py", line 236, in predict
    for ind, batch in enumerate(progress_bar):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\tqdm\std.py", line 1195, in __iter__
    for obj in iterable:
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\dataloader.py", line 530, in __next__
    data = self._next_data()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\dataloader.py", line 1224, in _next_data
    return self._process_data(data)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\dataloader.py", line 1250, in _process_data
    data.reraise()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\_utils.py", line 457, in reraise
    raise exception
OSError: Caught OSError in DataLoader worker process 3.
Original Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\worker.py", line 287, in _worker_loop
    data = fetcher.fetch(index)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\fetch.py", line 49, in fetch
    data = [self.dataset[idx] for idx in possibly_batched_index]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\fetch.py", line 49, in <listcomp>
    data = [self.dataset[idx] for idx in possibly_batched_index]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\datasets\vocal_dataset.py", line 75, in __getitem__
    spect = spect_dict[self.spect_key]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\npyio.py", line 243, in __getitem__
    return format.read_array(bytes,
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 778, in read_array
    data = _read_bytes(fp, read_size, "array data")
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 907, in _read_bytes
    r = fp.read(size - len(data))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 925, in read
    data = self._read1(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 995, in _read1
    data = self._read2(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 1025, in _read2
    data = self._fileobj.read(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 745, in read
    data = self._file.read(n)
OSError: [Errno 22] Invalid argument

NickleDave · 2022-05-19T14:02:02Z

Same thing for "2:" -- there's the --- Logging error --- events that do not force the program to halt execution (but would definitely worry me if I saw them)

creating dataset from spectrogram files in: manual\211225-220204\predict_data11
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
...
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'validating set of spectrogram files'
Arguments: ()
validating set of spectrogram files
[########################################] | 100% Completed |  1hr 27min 34.9s
--- Logging error ---
Traceback (most recent call last):
...
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'creating pandas.DataFrame representing dataset from spectrogram files'
Arguments: ()
creating pandas.DataFrame representing dataset from spectrogram files
[########################################] | 100% Completed |  1hr  0min 52.2s
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\logging\__init__.py", line 1104, in emit
...
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\logging.py", line 66, in log_or_print
    log_method(msg)
Message: 'saving dataset as a .csv file: manual\\211225-220204\\output\\prep\\predict_data11_prep_220518_071706.csv'
Arguments: ()
saving dataset as a .csv file: manual\211225-220204\output\prep\predict_data11_prep_220518_071706.csv

And then there's the final fatal error when vak predict runs that again appears to be an issue with accessing npz files.

  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\dataloader.py", line 1250, in _process_data
    data.reraise()
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\_utils.py", line 457, in reraise
    raise exception
OSError: Caught OSError in DataLoader worker process 3.
Original Traceback (most recent call last):
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\worker.py", line 287, in _worker_loop
    data = fetcher.fetch(index)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\fetch.py", line 49, in fetch
    data = [self.dataset[idx] for idx in possibly_batched_index]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\torch\utils\data\_utils\fetch.py", line 49, in <listcomp>
    data = [self.dataset[idx] for idx in possibly_batched_index]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\vak\datasets\vocal_dataset.py", line 75, in __getitem__
    spect = spect_dict[self.spect_key]
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\npyio.py", line 243, in __getitem__
    return format.read_array(bytes,
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 778, in read_array
    data = _read_bytes(fp, read_size, "array data")
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\site-packages\numpy\lib\format.py", line 907, in _read_bytes
    r = fp.read(size - len(data))
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 925, in read
    data = self._read1(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 995, in _read1
    data = self._read2(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 1025, in _read2
    data = self._fileobj.read(n)
  File "C:\Users\finch\anaconda3\envs\vak-env-cuda113\lib\zipfile.py", line 745, in read
    data = self._file.read(n)
OSError: [Errno 22] Invalid argument

A difference in this case being that it happened inside a torch DataLoader -- so it's not just dask that's experiencing this problem

NickleDave · 2022-05-19T14:03:01Z

This is starting to look similar to what @yardencsGitHub and I experienced on Windows previously:
#293

NickleDave · 2022-05-19T14:05:44Z

just trying to document that in detail to increase the likelihood other people find it when they search @fMizki

if you could reply to this comment above
#509 (comment)
I would really like to help you and see if we can make the experience on Windows better.
I think I might need to dig in deeper though -- if you can share env info + data to reproduce the bug that would really help, thank you

fMizki · 2022-05-20T13:31:46Z

Well, as we talked on the e-mail, I had been working on network drive, and this can be the cause, so I tried on the local drive.

(vak-env-cuda113) C:\Users\finch\OneDrive\デスクトップ>vak prep cyn191_predict11.toml && vak predict cyn191_predict11.toml
determined that purpose of config file is: predict
will add 'csv_path' option to 'PREDICT' section
purpose for dataset: predict
will not split dataset
creating dataset from spectrogram files in: predict_data11
validating set of spectrogram files
[########################################] | 100% Completed |  1min 40.2s
creating pandas.DataFrame representing dataset from spectrogram files
[########################################] | 100% Completed |  1min 34.0s
saving dataset as a .csv file: output\prep\predict_data11_prep_220520_213905.csv
Logging results to output\prep
loading SpectScaler from path: train\results\results_220515_113717\StandardizeSpect
loading labelmap from path: train\results\results_220515_113717\labelmap.json
loading dataset to predict from csv path: output\prep\predict_data11_prep_220520_213905.csv
will save annotations in .csv file: output\cyn191_predict11.annot.csv
dataset has timebins with duration: 0.00145
shape of input to networks used for predictions: torch.Size([1, 1025, 176])
instantiating models from model-config map:/n{'TweetyNet': {'optimizer': {'lr': 0.001}, 'network': {}, 'loss': {}, 'metrics': {}}}
loading checkpoint for TweetyNet from path: train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
Loading checkpoint from:
train\results\results_220515_113717\TweetyNet\checkpoints\max-val-acc-checkpoint.pt
running predict method of TweetyNet
batch 4999 / 5000: 100%|███████████████████████████████████████████████████████████| 5000/5000 [06:16<00:00, 13.28it/s]
  0%|                                                                                         | 0/5000 [00:00<?, ?it/s]converting predictions to annotations
100%|██████████████████████████████████████████████████████████████████████████████| 5000/5000 [05:58<00:00, 13.95it/s]

As you can see, I got no error though I tried on the same files with which I was getting the logging-error. Moreover, the time for the prep is greatly reduced. I will share this on #507

All of my problems seems to root in the working drive. I've never expected this. I'm learnig a lot.
So sorry for disturbing you so much and I really appreciate for your kindness.
Thank you!

NickleDave · 2022-05-20T14:24:44Z

🙌 🙌 🙌 🚀 🚀 🚀
Excellent, this is great news!

You do not have to apologize.
It's really helpful for you to test in this way--we wouldn't have known about it otherwise.
I'm sure other people will try running on a network drive and it will be much easier to us to help them troubleshoot now that we know.

I will raise an issue to add something about this to the docs and make sure to give you credit for your contribution.
I'm going to close this for now.

fMizki · 2022-05-21T08:03:54Z

Thank you!

fMizki added the BUG Something isn't working label May 18, 2022

fMizki mentioned this issue May 20, 2022

Fasten 'vak prep predict.toml' #507

Closed

NickleDave closed this as completed May 20, 2022

NickleDave mentioned this issue May 20, 2022

DOC: add "warning" callout that running on network drives can cause slowdowns/errors #510

Open

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

BUG:--- Logging error --- #509

BUG:--- Logging error --- #509

fMizki commented May 18, 2022

NickleDave commented May 18, 2022

NickleDave commented May 18, 2022

fMizki commented May 19, 2022

fMizki commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022 •

edited

Loading

NickleDave commented May 19, 2022 •

edited

Loading

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

fMizki commented May 20, 2022 •

edited

Loading

NickleDave commented May 20, 2022

fMizki commented May 21, 2022

BUG:--- Logging error --- #509

BUG:--- Logging error --- #509

Comments

fMizki commented May 18, 2022

NickleDave commented May 18, 2022

NickleDave commented May 18, 2022

fMizki commented May 19, 2022

fMizki commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022 • edited Loading

NickleDave commented May 19, 2022 • edited Loading

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

NickleDave commented May 19, 2022

fMizki commented May 20, 2022 • edited Loading

NickleDave commented May 20, 2022

fMizki commented May 21, 2022

NickleDave commented May 19, 2022 •

edited

Loading

NickleDave commented May 19, 2022 •

edited

Loading

fMizki commented May 20, 2022 •

edited

Loading