Aws-cli: rds download-db-log-file-portion returns incomplete content

[defanator]

In some cases, the "aws rds download-db-log-file-portion --output=text" returns incomplete log file (smaller than size announced in "aws rds describe-db-log-files").

For example:

$ aws rds describe-db-log-files --db-instance-identifier=mydb
...
{
    "LastWritten": 1442228388000,
    "LogFileName": "error/postgresql.log.2015-09-14-10",
    "Size": 812120
}
...

$ aws rds download-db-log-file-portion --db-instance-identifier=mydb --log-file-name="error/postgresql.log.2015-09-14-10" --output=text > file
$ stat -c "%s" file
442312

awscli version:

$ pip show awscli
Metadata-Version: 2.0
Name: awscli
Version: 1.8.2
Summary: Universal Command Line Environment for AWS.
Home-page: http://aws.amazon.com/cli/
Author: Amazon Web Services
Author-email: UNKNOWN
License: Apache License 2.0
Location: /usr/lib/python2.6/site-packages
Requires: botocore, colorama, argparse, rsa, docutils

What could be the reason for that?

[rayluo]

Not sure whether the network connection breaks during the data transmission.

If this happens frequently, you can try to use --debug to catch some log on stderr. For example:

$ aws s3 ls --debug 2>stderr.txt 1>stdout.txt 

[defanator]

@rayluo - this happens continuously, effect is 100% reproducible. Just checked 4 times with --debug:

$ aws rds download-db-log-file-portion --db-instance-identifier=mydb --log-file-name "error/postgresql.log.2015-09-14-10" --output=text --debug 1>file1 2>err1
$ aws rds download-db-log-file-portion --db-instance-identifier=mydb --log-file-name "error/postgresql.log.2015-09-14-10" --output=text --debug 1>file2 2>err2
$ aws rds download-db-log-file-portion --db-instance-identifier=mydb --log-file-name "error/postgresql.log.2015-09-14-10" --output=text --debug 1>file3 2>err3
$ aws rds download-db-log-file-portion --db-instance-identifier=mydb --log-file-name "error/postgresql.log.2015-09-14-10" --output=text --debug 1>file4 2>err4

Output and its size are the same:

$ md5sum file[1234]
421c8def143c99a6fa4887138184723d  file1
421c8def143c99a6fa4887138184723d  file2
421c8def143c99a6fa4887138184723d  file3
421c8def143c99a6fa4887138184723d  file4
$ stat -c '%s' file[1234]
442312
442312
442312
442312

stderrs have the same size but different md5 due to timestamps inside them:

$ stat -c '%s' err[1234]
463408
463408
463408
463408

I haven't noticed any network-related errors within the debug output, but found the following thing:

actual log file starts with (note the 'content-length': '450133'):

2015-09-16 04:33:09,177 - MainThread - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [POST]>
2015-09-16 04:33:09,178 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): rds.us-west-1.amazonaws.com
2015-09-16 04:33:10,134 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "POST / HTTP/1.1" 200 450133
2015-09-16 04:33:11,708 - MainThread - botocore.parsers - DEBUG - Response headers: {'x-amzn-requestid': '[request-id]', 'date': 'Wed, 16 Sep 2015 05:33:10 GMT', 'content-length': '450133', 'content-type': 'text/xml'}
2015-09-16 04:33:11,708 - MainThread - botocore.parsers - DEBUG - Response body:
<DownloadDBLogFilePortionResponse xmlns="http://rds.amazonaws.com/doc/2014-10-31/">
  <DownloadDBLogFilePortionResult>
    <Marker>6:812120</Marker>
    <LogFileData>           m.metric_id in ('22') and
    ...

and ends with:

</LogFileData>
    <AdditionalDataPending>true</AdditionalDataPending>
  </DownloadDBLogFilePortionResult>
  <ResponseMetadata>
    <RequestId>[request-id]</RequestId>
  </ResponseMetadata>
</DownloadDBLogFilePortionResponse>
2015-09-16 04:33:11,718 - MainThread - botocore.hooks - DEBUG - Event needs-retry.rds.DownloadDBLogFilePortion: calling handler <botocore.retryhandler.RetryHandler object at 0x3966190>
2015-09-16 04:33:11,718 - MainThread - botocore.retryhandler - DEBUG - No retry needed.
2015-09-16 04:33:11,718 - MainThread - botocore.hooks - DEBUG - Event after-call.rds.DownloadDBLogFilePortion: calling handler <awscli.errorhandler.ErrorHandler object at 0x3247d90>
2015-09-16 04:33:11,718 - MainThread - awscli.errorhandler - DEBUG - HTTP Response Code: 200

then there's another request (due to AdditionalDataPending=true, I suppose):

2015-09-16 04:33:11,724 - MainThread - botocore.endpoint - DEBUG - Making request for <botocore.model.OperationModel object at 0x3986750> (verify_ssl=True) with params: {'body': {'Action': 'DownloadDBLogFilePortion', 'Marker': '6:812120', 'Version': '2014-10-31', 'DBInstanceIdentifier': u'mydb', 'LogFileName': u'error/postgresql.log.2015-09-14-10'}, 'url': 'https://rds.us-west-1.amazonaws.com/', 'headers': {'User-Agent': 'aws-cli/1.8.2 Python/2.6.6 Linux/2.6.32-504.16.2.el6.x86_64'}, 'query_string': '', 'url_path': '/', 'method': 'POST'}

and it ends with 404:

2015-09-16 04:33:11,973 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "POST / HTTP/1.1" 200 404
2015-09-16 04:33:11,974 - MainThread - botocore.parsers - DEBUG - Response headers: {'x-amzn-requestid': '[request-id]', 'date': 'Wed, 16 Sep 2015 05:33:11 GMT', 'content-length': '404', 'content-type': 'text/xml'}
2015-09-16 04:33:11,974 - MainThread - botocore.parsers - DEBUG - Response body:
<DownloadDBLogFilePortionResponse xmlns="http://rds.amazonaws.com/doc/2014-10-31/">
  <DownloadDBLogFilePortionResult>
    <Marker>6:812120</Marker>
    <LogFileData/>
    <AdditionalDataPending>false</AdditionalDataPending>
  </DownloadDBLogFilePortionResult>
  <ResponseMetadata>
    <RequestId>[request-id]</RequestId>
  </ResponseMetadata>
</DownloadDBLogFilePortionResponse>

Please let me know if I can provide anything else to find the issue.

[defanator]

Any news on this?

[rayluo]

Would you mind to add 2 more parameters and try it again? Let me know if that makes any difference.

aws ... --max-items 99999999 --starting-token 0

[defanator]

Unfortunately we have no RDS logs large enough to check this (we did a number of DB optimizations and turned verbose logging off). I see that we have no chance to check with the logs from my initial report due to their unavailability.

I will try to check with the parameters you have provided as soon as I can.

Please let me know if there is anything we could help with for further investigation on this issue.

Thanks.

[defanator]

@rayluo I've just checked a couple of large log files with the "--max-items 99999999 --starting-token 0" parameters added. Doing this I was able to get much closer size of a log file eventually, but it still doesn't match to the announced one in describe-db-log-files, e.g.:

postgresql.log.2015-10-19-10 (5919838) - this is what describe-db-log-files returns, and

$ stat -c '%s' postgresql.log.2015-10-19-10
5919597

is the result of download-db-log-file-portion.

Please let me know if there is anything else I can provide.

[rayluo]

@defanator I tested it with AWS CLI 1.8.13 and 1.9.0. It works for me, basically.

Your describe-db-log-files result is slightly larger than your downloaded file. Does your file keep increasing all the time, so that its size increases between each describe-db-log-files and during your download-db-log-file-portion?

I do observe the opposite symptom though. The download file is several bytes larger than the original file. A diff indicates that the file downloaded by CLI contains some extra 000a (HEX) for each 10000-size block. A minor issue which we will need to look into.

By the way, you can also omit the --max-items 99999999 and only use --starting-token 0.

[rayluo]

I report the new issue at #1613. Closing this one soon.

[defanator]

@rayluo I'll try to check later this week and will let you know - thanks for the information.

[anbotero]

I know this has been Closed for some time now, but it’s been two weeks now where I’m also getting incomplete files. It used to be fine before that. This is pretty much what I’m always getting now at the end of the download command:

# User@Host: dbuser[dbuser] @  [0.0.0.0]  Id: 1276884490
 [Your log message was truncated]
</LogFileData>
    <Marker>15:16825770</Marker>
  </DownloadDBLogFilePortionResult>
  <ResponseMetadata>
    <RequestId>437a10ed-b6e7-33d7-c172-c749db6e3c8c</RequestId>
  </ResponseMetadata>
</DownloadDBLogFilePortionResponse>

2016-11-08 12:24:39,810 - MainThread - botocore.hooks - DEBUG - Event needs-retry.rds.DownloadDBLogFilePortion: calling handler <botocore.retryhandler.RetryHandler object at 0x217071e51>
2016-11-08 12:24:39,810 - MainThread - botocore.retryhandler - DEBUG - No retry needed.

This is the command I’m running:

aws rds --debug download-db-log-file-portion --db-instance-identifier mydb --log-file-name slowquery/engine.very-slow-queries.log.0 --starting-token 0 --output text > /tmp/engine.very-slow-queries.log.0

And this is the verion of awscli I’m running:

aws-cli/1.11.13 Python/2.7.10 Darwin/15.6.0 botocore/1.4.70

Do you know what else should I try? I tried doing it through the Web Console, and it file would also fail at some point. I swear it was fine before three weeks ago, at least, where I downloaded a 1GB log file through the CLI and another 3.3GB file through the Web Console.

[JordonPhillips]

@anbotero If the web console is failing, I have a strong feeling that there's an issue service-side. Another user reported similar issues recently with #2268. This does seem to indicate that it's recent. Let's consolidate over on that issue.

[defanator]

Hi everyone.

BTW, we're experiencing the same issue with almost all of our current logs (quite large, 1 hour log can reach up to 400-800Mb).

I'm going to reduce amount of logging and check if upgrading to latest awscli helps somehow.

[defanator]

For example:

$ aws --version
aws-cli/1.11.13 Python/2.7.12 FreeBSD/10.3-RELEASE-p3 botocore/1.4.70
$ aws --output=text rds describe-db-log-files --db-instance-identifier mydb | fgrep postgresql.log.2016-11-10-04
DESCRIBEDBLOGFILES  1478753974000   error/postgresql.log.2016-11-10-04  517913043
$ aws --output=text rds download-db-log-file-portion --starting-token 0 --db-instance-identifier mydb --log-file-name "error/postgresql.log.2016-11-10-04" > postgresql.log.2016-11-10-04
$ stat -f '%z' postgresql.log.2016-11-10-04 
32506973

No errors are being reported.

[eredi93]

+1 on this issue. for some reason, I can't download the full logs from the AWS api. i tried via the aws cli and the ruby sdk, with both i can download just part of logs.
i reckon you have a problem with the api. @JordonPhillips can you give us an update in this?

audit.log.0.2017-02-02-16-06.7223
download size: 33555584
api size: 100000728

audit.log.0.2017-02-02-16-14.7228
download size: 97520881
api size: 100000274

[estsauver]

I am currently unable to download postgres logs via the webconsole or via wget'ing the generated link.

[stephanlindauer]

@kyleknap can this ticket be reopened and can we get an estimation on when there will be a fix for this?

[marksher]

I found a workaround when opening a support ticket for anyone that wants to try it. It uses the REST interface rather than Boto or CLI.

https://github.com/aws/aws-cli/issues/2268#issuecomment-373803942

[anuthaharinimn]

1. can we able to download all the postgres logs in none shot?
2. can we able to export all the postgres logs to cloudwatch?