get_url gives confusing error message when destination already exists

[deivid-rodriguez]

SUMMARY

The current get_url docs for the force and dest parameter does not make it clear what the expected behavior is when dest exists and force is false (the default). I kind of expect that it just succeeds. In any case, I think the error message one currently gets is very confusing.

ISSUE TYPE

• Bug Report

COMPONENT NAME

get_url

ANSIBLE VERSION

ansible 2.6.3
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/home/deivid/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/dist-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.15rc1 (default, Apr 15 2018, 21:51:34) [GCC 7.3.0]

CONFIGURATION

OS / ENVIRONMENT

N/A

STEPS TO REPRODUCE

touch /tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz'
ansible localhost  -m get_url -a 'url=https://shellcheck.storage.googleapis.com/shellcheck-v0.5.0.linux.x86_64.tar.xz dest=/tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz'

EXPECTED RESULTS

I think... success. If not, a more helpful error message, like "destination already exists. Use `force: true` to force redownload, or specify a checksum to prevent it".

ACTUAL RESULTS

localhost | FAILED! => {
    "changed": false, 
    "dest": "/tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz", 
    "gid": 1000, 
    "group": "deivid", 
    "mode": "0644", 
    "msg": "Request failed", 
    "owner": "deivid", 
    "response": "HTTP Error 400: Bad Request", 
    "size": 3231336, 
    "state": "file", 
    "status_code": 400, 
    "uid": 1000, 
    "url": "https://shellcheck.storage.googleapis.com/shellcheck-v0.5.0.linux.x86_64.tar.xz"
}

[ansibot]

Files identified in the description:

• lib/ansible/modules/net_tools/basics/get_url.py

If these files are inaccurate, please update the component name section of the description or use the !component bot command.

click here for bot help

[ansibot]

cc @jpmens @ptux
click here for bot help

[sivel]

I cannot duplicate this issue.

The only thing that I can assume, is that the result of touch on your system, or the conversion of the mtime to the format required for If-Modified-Since is producing a value that is causing the server to respond with a 400 Bad Request.

Can you run the following for me?

python -c 'import os, datetime; mtime = os.path.getmtime("/tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz"); print(mtime); last_mod_time = datetime.datetime.utcfromtimestamp(mtime); print(last_mod_time); print(last_mod_time.strftime("%a, %d %b %Y %H:%M:%S +0000"));'

As of right now, this produces the following for me:

1535569134.668752
2018-08-29 18:58:54.668752
Wed, 29 Aug 2018 18:58:54 +0000

needs_info

[deivid-rodriguez]

@sivel Thanks for the reply.

Probably adding the touch was misleading, I can reproduce the issue by running the command twice in a row.

The result of your command after touching for me is:

1535570102.63
2018-08-29 19:15:02.626249
Wed, 29 Aug 2018 19:15:02 +0000

[deivid-rodriguez]

A very random guess, but I though I'd mention it, since last time I reported an issue to a python repo, I was the only one getting it, and it was due to this issue.

Sometimes the standard urllib in python has trouble with my internet connection. I investigated it a while ago, and it was due to this python issue. Does ansible use urllib under the hood?

[sivel]

A very random guess, but I though I'd mention it, since last time I reported an issue to a python repo, I was the only one getting it, and it was due to this issue.

Sometimes the standard urllib in python has trouble with my internet connection. I investigated it a while ago, and it was due to this python issue. Does ansible use urllib under the hood?

Yes, ansible utilizes urllib2 under the hood for making requests.

FWIW, I tested with both touch and running the command 2 times. I cannot think of why you would get a 400 Bad Request, based on that info provided above.

It's not expected, and for whatever reason, something that is being sent in the request is causing the remote server to respond that way. The only thing I can imagine is the If-Modified-Since but the value you have shown, is valid and works for me.

I don't know of an easy way to debug this, other than using some what to intercept the request and response using something like mitmproxy.

If you are able to install mitmproxy (python library), and run it (mitmproxy), then you could execute your ansible command like:

http_proxy=http://127.0.0.1:8080 https_proxy=http://127.0.0.1:8080 ansible localhost -m get_url -a 'url=https://shellcheck.storage.googleapis.com/shellcheck-v0.5.0.linux.x86_64.tar.xz dest=/tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz validate_certs=false'

That gives me something like the following:

Request:

Accept-Encoding:    identity
Host:               shellcheck.storage.googleapis.com
User-Agent:         ansible-httpget
If-Modified-Since:  Wed, 29 Aug 2018 18:58:54 +0000
Connection:         close

Response:

X-GUploader-UploadID:  AEnB2UovcxuW6WX9sf5dyKdUBUq2IKsOUmxHhqFyAs5wkT7WrGeUratd02_XuFlW-fA9Ts3eLe1tkcVagKnnyJFHiOzwierDSQ
Expires:               Wed, 29 Aug 2018 19:29:34 GMT
Date:                  Wed, 29 Aug 2018 19:29:34 GMT
Cache-Control:         private, max-age=0
Last-Modified:         Fri, 01 Jun 2018 03:49:22 GMT
Content-Length:        0
Server:                UploadServer
Alt-Svc:               quic=":443"; ma=2592000; v="44,43,39,35"
Connection:            close

The status code isn't listed there, but I got a 304 Not Modified.

[deivid-rodriguez]

Nice, thanks! Yeah, I was terribly confused by this "Bad request" error.

I'll try to log the request & response using the way you mentioned. The information you show is "compatible" with the issue with urllib I mentioned, since the problem was the Connection: close header that the library adds by default. For example, in linuxmint/cinnamon#5926 (comment), I managed to fix the issue I was having by changing the code to not use urllib, so I could avoid sending that header, and that fixed the issue.

Anyways, I'll run the steps you mentioned and report my results here. 👍

[deivid-rodriguez]

@sivel You nailed it! Nothing related to my suspicions, but totally related to yours! It's a bad character in the If-Modified-Since header.

Request

Accept-Encoding:    identity                                                                                                                                           
Host:               shellcheck.storage.googleapis.com                                                                                                                  
User-Agent:         ansible-httpget                                                                                                                                    
Connection:         close                                                                                                                                              
If-Modified-Since:  mi\xc3\xa9, 29 ago 2018 19:16:15 +0000

Response Headers

X-GUploader-UploadID:  AEnB2UoySXIv1I0tyNlqFyCDAmO2Q8PwPCYpL4jbfJ8OJrseSyjEvlcT4HPpWK_-iBd0U6ZIowdnErGZBh6m87JcncmOQ1DEdg                                              
Expires:               Wed, 29 Aug 2018 20:09:22 GMT                                                                                                                   
Date:                  Wed, 29 Aug 2018 20:09:22 GMT                                                                                                                   
Cache-Control:         private, max-age=0                                                                                                                              
Last-Modified:         Fri, 01 Jun 2018 03:49:22 GMT                                                                                                                   
Content-Type:          application/xml; charset=UTF-8                                                                                                                  
Content-Length:        186                                                                                                                                             
Server:                UploadServer                                                                                                                                    
Alt-Svc:               quic=":443"; ma=2592000; v="44,43,39,35"                                                                                                        
Connection:            close                                                                                                                                           

Response body

<?xml version='1.0' encoding='UTF-8'?>
<Error>
  <Code>InvalidArgument</Code>
  <Message>Invalid argument.</Message>
  <Details>If-Modified-Since:mié, 29 ago 2018 19:16:15 +0000</Details>
</Error>

[deivid-rodriguez]

It sounds like ansible shouldn't be localizing the date that it's sent in this header?

[deivid-rodriguez]

LANG=C ansible localhost -m get_url -a 'url=https://shellcheck.storage.googleapis.com/shellcheck-v0.5.0.linux.x86_64.tar.xz dest=/tmp/shellcheck-v0.5.0.linux.x86_64.tar.xz'

works just fine.

[sivel]

I believe you are correct, but I'm not sure we can rely on the strftime functionality in python at that point. We may need to handle it ourselves.

I'll have to do more research here.

[deivid-rodriguez]

Well, thanks so much for your support, it was really helpful!

[sivel]

I have a pull request that should resolve this issue: #44868

[deivid-rodriguez]

I confirm that the PR fixes my issue, thanks a lot! ❤️

[sivel]

Great! I'm re-evaluating a few assumptions, just to see if I can not duplicate the formatting code. Once I've completed that and tests are passing, I'll get that PR merged.