ACL Issue - Status code 500 when authorization is included

[ahalota]

This issue is recent, as previously I had no issues with the code posted below. I updated my instance of h5serv in late December 2016 to match the later releases (last updated around July 2016), and since then have seen this issue. I don't know the exact details of when it was updated, but will have that information soon and can post it here then. It's possible the issue is on my end, but I'd like to check if it was related to any code changes as well.

The URL I'm including here is actually live so you should be able to try this issue out on your own as well.

import requests
import base64

rsp = requests.get('http://globalfiredata.gsfc.nasa.gov:3000',
                              headers={'host': 'GFED_FC.globalfiredata.gsfc.nasa.gov:3000',
                                              'authorization' : 'Basic ' + base64.b64encode(user+':'+password) }, 
                              )

if (rsp.status_code != 200):
    print "Main endpoint request failed with code", rsp.status_code
    return rsp.status_code

With user and password being associated with a user that has crudep rights on the file, and default user having cudep rights on the file (set using the admin tools).

It used to work fine, but now rsp.status_code is returning 500 (internal server error) instead of 200, as it used to.

If I remove the header for the authorization, THEN the request returns 200 no problem.

[jreadey]

Hi, can you provide a trace from the server log? You can send to my email (jreadey AT hdfgroup DOT org) if you don't want to make it public on github.

[ahalota]

2017-01-13 18:33:05,475:INFO:app.py:3067::RootHandler.get GFED_FC.globalfiredata.gsfc.nasa.gov 2017-01-13 18:33:05,476:INFO:app.py:3068::remote_ip: 192.168.200.12 2017-01-13 18:33:05,477:INFO:app.py:204::getFilePath: GFED_FC.globalfiredata.gsfc.nasa.gov 2017-01-13 18:33:05,477:INFO:app.py:206::tocFilePath: /usr/anaconda2/data/.toc.h5 2017-01-13 18:33:05,479:INFO:fileUtil.py:266::verifyFile('/usr/anaconda2/data/GFED_FC.h5', False) 2017-01-13 18:33:05,481:INFO:hdf5db.py:163::init -- filePath: /usr/anaconda2/data/GFED_FC.h5 mode: r+ 2017-01-13 18:33:05,489:INFO:hdf5db.py:194::Hdf5db enter 2017-01-13 18:33:05,490:INFO:hdf5db.py:713::getUUIDByPath: [/] 2017-01-13 18:33:05,494:INFO:hdf5db.py:198::Hdf5db exit 2017-01-13 18:33:05,496:INFO:app.py:3087::X-header: [Accept-Encoding] value: [gzip, deflate] 2017-01-13 18:33:05,496:INFO:app.py:3087::X-header: [X-Forwarded-For] value: [128.183.160.225] 2017-01-13 18:33:05,496:INFO:app.py:3087::X-header: [Connection] value: [keep-alive] 2017-01-13 18:33:05,496:INFO:app.py:3087::X-header: [Accept] value: [/] 2017-01-13 18:33:05,497:INFO:app.py:3087::X-header: [User-Agent] value: [python-requests/2.8.1] 2017-01-13 18:33:05,497:INFO:app.py:3087::X-header: [Host] value: [GFED_FC.globalfiredata.gsfc.nasa.gov] 2017-01-13 18:33:05,497:INFO:app.py:204::getFilePath: GFED_FC.globalfiredata.gsfc.nasa.gov 2017-01-13 18:33:05,497:INFO:app.py:206::tocFilePath: /usr/anaconda2/data/.toc.h5 2017-01-13 18:33:05,498:INFO:fileUtil.py:266::verifyFile('/usr/anaconda2/data/GFED_FC.h5', False) 2017-01-13 18:33:05,499:INFO:app.py:3091::filepath: /usr/anaconda2/data/GFED_FC.h5 2017-01-13 18:33:05,507:INFO:app.py:3067::RootHandler.get GFED_FC.globalfiredata.gsfc.nasa.gov:3000 2017-01-13 18:33:05,507:INFO:app.py:3068::remote_ip: 192.168.200.12 2017-01-13 18:33:05,507:INFO:app.py:204::getFilePath: GFED_FC.globalfiredata.gsfc.nasa.gov:3000 2017-01-13 18:33:05,508:INFO:app.py:206::tocFilePath: /usr/anaconda2/data/.toc.h5 2017-01-13 18:33:05,509:INFO:fileUtil.py:266::verifyFile('/usr/anaconda2/data/GFED_FC.h5', False) 2017-01-13 18:33:05,510:INFO:hdf5db.py:163::init -- filePath: /usr/anaconda2/data/GFED_FC.h5 mode: r+ 2017-01-13 18:33:05,513:INFO:hdf5db.py:194::Hdf5db enter 2017-01-13 18:33:05,513:INFO:hdf5db.py:713::getUUIDByPath: [/] 2017-01-13 18:33:05,517:INFO:hdf5db.py:198::Hdf5db exit 2017-01-13 18:33:05,518:INFO:app.py:3087::X-header: [Accept-Encoding] value: [gzip, deflate] 2017-01-13 18:33:05,519:INFO:app.py:3087::X-header: [X-Forwarded-For] value: [128.183.160.225] 2017-01-13 18:33:05,519:INFO:app.py:3087::X-header: [Connection] value: [keep-alive] 2017-01-13 18:33:05,519:INFO:app.py:3087::X-header: [Accept] value: [/] 2017-01-13 18:33:05,519:INFO:app.py:3087::X-header: [User-Agent] value: [python-requests/2.8.1] 2017-01-13 18:33:05,519:INFO:app.py:3087::X-header: [Host] value: [GFED_FC.globalfiredata.gsfc.nasa.gov:3000] 2017-01-13 18:33:05,520:INFO:app.py:204::getFilePath: GFED_FC.globalfiredata.gsfc.nasa.gov:3000 2017-01-13 18:33:05,520:INFO:app.py:206::tocFilePath: /usr/anaconda2/data/.toc.h5 2017-01-13 18:33:05,521:INFO:fileUtil.py:266::verifyFile('/usr/anaconda2/data/GFED_FC.h5', False) 2017-01-13 18:33:05,521:INFO:app.py:3091::filepath: /usr/anaconda2/data/GFED_FC.h5 2017-01-13 18:33:06,385:INFO:app.py:3067::RootHandler.get GFED_FC.globalfiredata.gsfc.nasa.gov:3000 2017-01-13 18:33:06,386:INFO:app.py:3068::remote_ip: 192.168.200.12

This is all the contents of the log after running the request shown in the code above.

[jreadey]

The log output doesn't seem to correspond to what's in either the develop or master branch. I.e. I see RootHandler.get on line 2814 not 3067. Are you sure the latest code is running?

[jreadey]

@ahalota - any update on this? Are you still seeing this problem?

[ahalota]

Yes, it looks like this was an install from October. Unfortunately I'm one step removed from when this was loaded onto our production machine so it's taking me a while to figure out what exactly was done.

[jreadey]

Can you reproduce on your desktop machine? If not, it might be a configuration issue on the production machine.

[ahalota]

Hmm...I tried to reproduce it on my machine, but it seems to not be acting up.

When I use an invalid user to authenticate on a fresh local set-up, I get error 401. When I use an invalid user to authenticate on my live set-up, I get error 500.

A valid user gets access locally, but still gets error 500 on my live set-up.

Both work fine if I do not include ANY authorization.

[ahalota]

I'm reviewing my log to figure this out, and notice that i only get the "INFO" messages. I believe I have log level set to info, shouldn't that also include any errors, or are those stored elswhere?

[jreadey]

All the log messages go to the same file. Do you see WARNING messages in the log file?

[ahalota]

Nope. I am testing now on my local set-up. The log_level is set to 'INFO' and in my command line where I started the server, I do see 'WARNING' messages. However, my output log ONLY shows the INFO messages.

Putting this in a separate issue: https://github.com/HDFGroup/h5serv/issues/107

[jreadey]

That's really strange. You are looking at the log/h5serv.log file?

Anyway, are you getting the 500 errors on your local setup? If you can grab a stack trace from the log (or h5serv output) that would be really helpful.

[ahalota]

No, I can't reproduce it unfortunately. I'd like to see where I went wrong, but I'll likely just try to revert to the previous copy I had that was running ok. The exact output when adding an authorization on my live copy is:

<html><title>500: Internal Server Error</title><body>500: Internal Server Error</body></html>

Which doesn't look at all like what gets sent out from h5server, so it's likely unrelated...

[ahalota]

Solved the problem by going back to my original install, still no clue what the difference was. Maybe my latest download was at some weird in between point. Either way, I give up on diagnosing the issue, it's solved for now.