search

dandi / dandi-archive

DANDI API server and Web app
https://dandiarchive.org
14 stars 10 forks source link

fails to post assets #65

Closed yarikoptic closed 3 years ago

yarikoptic commented 3 years ago

now that we got upload going, ran into

(Pdb) p url, parameters, _headers
('https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/', {}, {'accept': 'application/json'})
(Pdb) p result.text
'\n<!doctype html>\n<html lang="en">\n<head>\n  <title>Server Error (500)</title>\n</head>\n<body>\n  <h1>Server Error (500)</h1><p></p>\n</body>\n</html>\n'

and "Authorization: token XXX" was provided... (but not shown above)

NB moved view issue into https://github.com/dandi/dandiarchive/issues/554

@dchiquit could you teach me how to get to the api sever logs?

yarikoptic commented 3 years ago

eh, I was not correct in my description -- it is not GET but POST which fails for me 

2021-01-25 18:15:38,832 [   DEBUG] Waiting for server-side validation to complete
2021-01-25 18:15:38,832 [   DEBUG] GET https://api.dandiarchive.org/api/uploads/validations/1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c/
2021-01-25 18:15:39,116 [   DEBUG] Response: 200
2021-01-25 18:15:39,117 [   DEBUG] Assigning asset blob to dandiset & version
{'status': 'producing asset'}
2021-01-25 18:15:39,117 [   DEBUG] POST https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/
2021-01-25 18:15:39,879 [   DEBUG] Response: 500
2021-01-25 18:15:39,880 [   DEBUG] Error 500 while sending POST request to https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/: 
<!doctype html>
<html lang="en">
<head>
  <title>Server Error (500)</title>
</head>
<body>
  <h1>Server Error (500)</h1><p></p>
</body>
</html>

2021-01-25 18:15:39,885 [   DEBUG] Caught exception Error 500 while sending POST request to https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/
2021-01-25 18:15:39,887 [    INFO] Logs saved in /home/yoh/.cache/dandi-cli/log/20210125231532Z-3746721.log
Traceback (most recent call last):
  File "/home/yoh/proj/dandi/dandi-cli-master/venvs/dev3/bin/dandi", line 33, in <module>
    sys.exit(load_entry_point('dandi', 'console_scripts', 'dandi')())
  File "/usr/lib/python3/dist-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/lib/python3/dist-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/lib/python3/dist-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/lib/python3/dist-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/click/decorators.py", line 33, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/cli/base.py", line 107, in wrapper
    return f(*args, **kwargs)
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/cli/cmd_upload.py", line 98, in upload
    upload(
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/upload.py", line 52, in upload
    return _new_upload(
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/upload.py", line 869, in _new_upload
    for v in process_path(path, relpath):
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/upload.py", line 813, in process_path
    for r in client.iter_upload(
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py", line 466, in iter_upload
    self.post(
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py", line 183, in post
    return self.send_request(
  File "/home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py", line 147, in send_request
    raise requests.HTTPError(msg, response=result)
requests.exceptions.HTTPError: Error 500 while sending POST request to https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/

> /home/yoh/proj/dandi/dandi-cli-master/dandi/dandiapi.py(147)send_request()
-> raise requests.HTTPError(msg, response=result)
(Pdb) p result.text
'\n<!doctype html>\n<html lang="en">\n<head>\n  <title>Server Error (500)</title>\n</head>\n<body>\n  <h1>Server Error (500)</h1><p></p>\n</body>\n</html>\n'
(Pdb) p url
'https://api.dandiarchive.org/api/dandisets/000009/versions/draft/assets/'
(Pdb) p json
{'path': 'sub-RAT123/sub-RAT123.nwb', 'metadata': {'schemaVersion': '1.0.0-rc1', 'identifier': 'TEST_Subject', 'access': [{'status': 'dandi:Open'}], 'repository': 'https://dandiarchive.org/', 'wasGeneratedBy': {'identifier': '1a946c9f-4e1b-4b4a-b914-98d3f153504a', 'name': 'Metadata generation', 'description': 'Metadata generated by DANDI cli', 'wasAssociatedWith': {'identifier': {'value': 'SCR_019009', 'propertyID': 'RRID'}, 'name': 'DANDI Command Line Interface'}}, 'contentSize': 18792, 'encodingFormat': 'application/x-nwb', 'digest': {'value': '1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c', 'cryptoType': 'dandi:SHA256'}, 'wasDerivedFrom': [{}], 'wasAttributedTo': [{'identifier': 'RAT123', 'sex': {'identifier': 'http://purl.obolibrary.org/obo/PATO_0000384', 'name': 'Male'}, 'genotype': 'WT', 'species': {'identifier': 'http://purl.obolibrary.org/obo/NCBITaxon_10116', 'name': 'Brown rat'}}]}, 'sha256': '1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c'}
dchiquito commented 3 years ago

Logs are stored in a Heroku service, so Heroku access is required to view them. I dug these out of the logs:

Jan 25 15:15:39 dandi-api app/web.1 10.123.249.13 - - [25/Jan/2021:23:15:38 +0000] "GET /api/uploads/validations/1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c/ HTTP/1.1" 200 180 "-" "python-requests/2.24.0"
Jan 25 15:15:39 dandi-api app/worker.1 [2021-01-25 23:15:38,866: INFO/ForkPoolWorker-8] dandiapi.api.tasks.validate[07199a73-8232-4367-8d4b-18d2cb16ffe6]: Calculated sha256 1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c
Jan 25 15:15:39 dandi-api app/worker.1 [2021-01-25 23:15:38,897: INFO/ForkPoolWorker-8] Task dandiapi.api.tasks.validate[07199a73-8232-4367-8d4b-18d2cb16ffe6] succeeded in 2.784739121911116s: None
Jan 25 15:15:39 dandi-api heroku/router at=info method=GET path="/api/uploads/validations/1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c/" host=api.dandiarchive.org request_id=9246cfe2-7a24-45c0-80d5-f1654fac3192 fwd="76.24.253.1" dyno=web.1 connect=0ms service=236ms status=200 bytes=483 protocol=https
Jan 25 15:15:39 dandi-api app/web.1 10.123.249.13 - - [25/Jan/2021:23:15:39 +0000] "GET /api/uploads/validations/1a765509384ea96b7b12136353d9c5b94f23d764ad0431e049197f7875eb352c/ HTTP/1.1" 200 178 "-" "python-requests/2.24.0"
Jan 25 15:15:40 dandi-api heroku/router at=info method=POST path="/api/dandisets/000009/versions/draft/assets/" host=api.dandiarchive.org request_id=ea785e36-c90e-45db-9691-9fc16b9a8a9d fwd="76.24.253.1" dyno=web.1 connect=0ms service=652ms status=500 bytes=433 protocol=https
Jan 25 15:15:40 dandi-api app/web.1 [23:15:39] ERROR    Internal Server Error:                            log.py:222
Jan 25 15:15:40 dandi-api app/web.1                     /api/dandisets/000009/versions/draft/assets/                
Jan 25 15:15:40 dandi-api app/web.1                     Traceback (most recent call last):                          
Jan 25 15:15:40 dandi-api app/web.1                       File "/app/.heroku/python/lib/python3.8/site-pa           
Jan 25 15:15:40 dandi-api app/web.1                     ckages/django/db/backends/utils.py", line 86, in            
Jan 25 15:15:40 dandi-api app/web.1                     _execute                                                    
Jan 25 15:15:40 dandi-api app/web.1                         return self.cursor.execute(sql, params)                 
Jan 25 15:15:40 dandi-api app/web.1                     psycopg2.errors.UniqueViolation: duplicate key              
Jan 25 15:15:40 dandi-api app/web.1                     value violates unique constraint                            
Jan 25 15:15:40 dandi-api app/web.1                     "api_asset_path_version_id_0267c3d9_uniq"                   
Jan 25 15:15:40 dandi-api app/web.1                     DETAIL:  Key (path,                                         
Jan 25 15:15:40 dandi-api app/web.1                     version_id)=(sub-RAT123/sub-RAT123.nwb, 10)                 
Jan 25 15:15:40 dandi-api app/web.1                     already exists.                                             
... lots more stack trace ...
Jan 25 15:15:40 dandi-api app/web.1                       File "/app/.heroku/python/lib/python3.8/site-pa           
Jan 25 15:15:40 dandi-api app/web.1                     ckages/django/db/utils.py", line 90, in __exit__            
Jan 25 15:15:40 dandi-api app/web.1                         raise dj_exc_value.with_traceback(traceback)            
Jan 25 15:15:40 dandi-api app/web.1                     from exc_value                                              
Jan 25 15:15:40 dandi-api app/web.1                       File "/app/.heroku/python/lib/python3.8/site-pa           
Jan 25 15:15:40 dandi-api app/web.1                     ckages/django/db/backends/utils.py", line 86, in            
Jan 25 15:15:40 dandi-api app/web.1                     _execute                                                    
Jan 25 15:15:40 dandi-api app/web.1                         return self.cursor.execute(sql, params)                 
Jan 25 15:15:40 dandi-api app/web.1                     django.db.utils.IntegrityError: duplicate key               
Jan 25 15:15:40 dandi-api app/web.1                     value violates unique constraint                            
Jan 25 15:15:40 dandi-api app/web.1                     "api_asset_path_version_id_0267c3d9_uniq"                   
Jan 25 15:15:40 dandi-api app/web.1                     DETAIL:  Key (path,                                         
Jan 25 15:15:40 dandi-api app/web.1                     version_id)=(sub-RAT123/sub-RAT123.nwb, 10)                 
Jan 25 15:15:40 dandi-api app/web.1                     already exists.                                             
Jan 25 15:15:40 dandi-api app/web.1 10.123.249.13 - - [25/Jan/2021:23:15:39 +0000] "POST /api/dandisets/000009/versions/draft/assets/ HTTP/1.1" 500 145 "-" "python-requests/2.24.0"
dchiquito commented 3 years ago

It looks like you are trying to create a new Asset with POST /api/dandisets/000009/versions/draft/assets/, but that asset already exists. I would recommend checking if the asset already exists, and if it does, do a PUT to update it.

We could extend the POST to handle this case and modify the existing asset if it exists, but I personally think that pollutes the cleanliness of the API.

yarikoptic commented 3 years ago

All assets are unique (uuid is minted, we never modify the asset, only create new ones, and eventually gc unused). But I might indeed be trying to create a new asset with path for which another asset already exists. I guess that is the case here. I can handle that in client indeed although it would be racy. Don't think we should add "overwrite" option to API for now. Server should error out informatively nevertheless if there is path "collision"