rds download-db-log-file-portion -> encoding issue

[matheusoliveira]

I was debugging a problem with different size reported by describe-db-log-files and the size downloaded with download-db-log-file-portion, like the one reported on #1504, and I found out that when you have unicode characters in the log file the aws-cli client won't download it properly.

Version: aws-cli/1.11.36 Python/2.7.13 Linux/4.10.13-200.fc25.x86_64 botocore/1.4.93

That is easily reproducible, I executed the following on a PostgreSQL instance after setting log_min_duration_statement=0 on the parameter group:

SELECT 'ãçeñt';

The file downloaded as:

aws rds download-db-log-file-portion --starting-token 0 --output text --db-instance-identifier my-instance --log-file-name error/postgresql.log.2017-07-21-18 > /tmp/test.log

The line on the file taken from the above command is:

2017-07-21 18:00:20 UTC:10.254.14.213(56324):my-instance@my-db:[4651]:LOG:  duration: 6.246 ms  statement: SELECT '????e??t';

While the same line on the file downloaded through AWS web console is:

2017-07-21 18:00:20 UTC:10.254.14.213(56324):my-instance@my-db:[4651]:LOG:  duration: 6.246 ms  statement: SELECT 'ãçeñt';

I haven't found issues related (please forgive me if that is a known issue). Am I doing something wrong or is it really a bug on aws-cli or Boto?

I can do more trials if needed, and I can help debugging more.

[kyleknap]

Would it be possible to run this command again with --debug? Since the content is getting redirected to a file, it is difficult to tell if it is the CLI is losing the encoding or the encoding is getting lost in the redirection.

[matheusoliveira]

Sure, I got the following output (I have collapsed the log part on LogFileData tag to just the begining and the end, which shows the encoding issue also on the terminal):

$ aws rds download-db-log-file-portion --debug --starting-token 0 --output text --db-instance-identifier test-mo --log-file-name error/postgresql.log.2017-07-27-14 > /tmp/postgresql.log.2017-07-27-14
2017-07-27 11:39:13,395 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/1.11.36 Python/2.7.13 Linux/4.10.13-200.fc25.x86_64 botocore/1.4.93
2017-07-27 11:39:13,395 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['rds', 'download-db-log-file-portion', '--debug', '--starting-token', '0', '--output', 'text', '--db-instance-identifier', 'test-mo', '--log-file-name', 'error/postgresql.log.2017-07-27-14']
2017-07-27 11:39:13,395 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_scalar_parsers at 0x7f4c22381410>
2017-07-27 11:39:13,395 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7f4c22872578>
2017-07-27 11:39:13,398 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/lib/python2.7/site-packages/botocore/data/rds/2014-10-31/service-2.json
2017-07-27 11:39:13,427 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/lib/python2.7/site-packages/botocore/data/rds/2014-10-31/service-2.sdk-extras.json
2017-07-27 11:39:13,427 - MainThread - botocore.hooks - DEBUG - Event service-data-loaded.rds: calling handler <function register_retries_for_service at 0x7f4c23101e60>
2017-07-27 11:39:13,427 - MainThread - botocore.handlers - DEBUG - Registering retry handlers for service: rds
2017-07-27 11:39:13,430 - MainThread - botocore.hooks - DEBUG - Event building-command-table.rds: calling handler <function _building_command_table at 0x7f4c22419f50>
2017-07-27 11:39:13,430 - MainThread - botocore.hooks - DEBUG - Event service-data-loaded.rds: calling handler <function register_retries_for_service at 0x7f4c23101e60>
2017-07-27 11:39:13,430 - MainThread - botocore.handlers - DEBUG - Registering retry handlers for service: rds
2017-07-27 11:39:13,431 - MainThread - botocore.hooks - DEBUG - Event building-command-table.rds: calling handler <function add_waiters at 0x7f4c223865f0>
2017-07-27 11:39:13,432 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/lib/python2.7/site-packages/botocore/data/rds/2014-10-31/waiters-2.json
2017-07-27 11:39:13,434 - MainThread - awscli.clidriver - DEBUG - OrderedDict([(u'db-instance-identifier', <awscli.arguments.CLIArgument object at 0x7f4c220817d0>), (u'log-file-name', <awscli.arguments.CLIArgument object at 0x7f4c22081790>), (u'marker', <awscli.arguments.CLIArgument object at 0x7f4c2209a0d0>), (u'number-of-lines', <awscli.arguments.CLIArgument object at 0x7f4c2209a110>)])
2017-07-27 11:39:13,434 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.rds.download-db-log-file-portion: calling handler <function add_streaming_output_arg at 0x7f4c22381938>
2017-07-27 11:39:13,434 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.rds.download-db-log-file-portion: calling handler <function add_cli_input_json at 0x7f4c227fd398>
2017-07-27 11:39:13,434 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.rds.download-db-log-file-portion: calling handler <function unify_paging_params at 0x7f4c22415938>
2017-07-27 11:39:13,436 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/lib/python2.7/site-packages/botocore/data/rds/2014-10-31/paginators-1.json
2017-07-27 11:39:13,436 - MainThread - awscli.customizations.paginate - DEBUG - Modifying paging parameters for operation: DownloadDBLogFilePortion
2017-07-27 11:39:13,436 - MainThread - botocore.hooks - DEBUG - Event building-argument-table.rds.download-db-log-file-portion: calling handler <function add_generate_skeleton at 0x7f4c223fccf8>
2017-07-27 11:39:13,437 - MainThread - botocore.hooks - DEBUG - Event before-building-argument-table-parser.rds.download-db-log-file-portion: calling handler <bound method CliInputJSONArgument.override_required_args of <awscli.customizations.cliinputjson.CliInputJSONArgument object at 0x7f4c2209a150>>
2017-07-27 11:39:13,437 - MainThread - botocore.hooks - DEBUG - Event before-building-argument-table-parser.rds.download-db-log-file-portion: calling handler <bound method GenerateCliSkeletonArgument.override_required_args of <awscli.customizations.generatecliskeleton.GenerateCliSkeletonArgument object at 0x7f4c2209a550>>
2017-07-27 11:39:13,437 - MainThread - botocore.hooks - DEBUG - Event operation-args-parsed.rds.download-db-log-file-portion: calling handler <functools.partial object at 0x7f4c21b6c7e0>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.db-instance-identifier: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.rds.download-db-log-file-portion: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f4c2284fc90>
2017-07-27 11:39:13,438 - MainThread - awscli.arguments - DEBUG - Unpacked value of u'test-mo' for parameter "db_instance_identifier": u'test-mo'
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.log-file-name: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.rds.download-db-log-file-portion: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f4c2284fc90>
2017-07-27 11:39:13,438 - MainThread - awscli.arguments - DEBUG - Unpacked value of u'error/postgresql.log.2017-07-27-14' for parameter "log_file_name": u'error/postgresql.log.2017-07-27-14'
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.marker: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.number-of-lines: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.cli-input-json: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.starting-token: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.page-size: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.max-items: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,438 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.rds.download-db-log-file-portion.generate-cli-skeleton: calling handler <function uri_param at 0x7f4c228901b8>
2017-07-27 11:39:13,439 - MainThread - botocore.hooks - DEBUG - Event calling-command.rds.download-db-log-file-portion: calling handler <bound method GenerateCliSkeletonArgument.generate_json_skeleton of <awscli.customizations.generatecliskeleton.GenerateCliSkeletonArgument object at 0x7f4c2209a550>>
2017-07-27 11:39:13,439 - MainThread - botocore.hooks - DEBUG - Event calling-command.rds.download-db-log-file-portion: calling handler <bound method CliInputJSONArgument.add_to_call_parameters of <awscli.customizations.cliinputjson.CliInputJSONArgument object at 0x7f4c2209a150>>
2017-07-27 11:39:13,439 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2017-07-27 11:39:13,439 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role
2017-07-27 11:39:13,439 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file
2017-07-27 11:39:13,439 - MainThread - botocore.credentials - INFO - Found credentials in shared credentials file: ~/.aws/credentials
2017-07-27 11:39:13,439 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/lib/python2.7/site-packages/botocore/data/endpoints.json
2017-07-27 11:39:13,471 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: rds
2017-07-27 11:39:13,475 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.rds: calling handler <function add_generate_presigned_url at 0x7f4c23152320>
2017-07-27 11:39:13,476 - MainThread - botocore.args - DEBUG - The s3 config key is not a dictionary type, ignoring its value of: None
2017-07-27 11:39:13,478 - MainThread - botocore.endpoint - DEBUG - Setting rds timeout as (60, 60)
2017-07-27 11:39:13,479 - MainThread - botocore.paginate - DEBUG - Attempting to fall back to old starting token parser. For token: 0
2017-07-27 11:39:13,479 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.rds.DownloadDBLogFilePortion: calling handler <function generate_idempotent_uuid at 0x7f4c231018c0>
2017-07-27 11:39:13,480 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=DownloadDBLogFilePortion) (verify_ssl=True) with params: {'body': {'Action': u'DownloadDBLogFilePortion', u'Marker': u'0', 'Version': u'2014-10-31', u'LogFileName': u'error/postgresql.log.2017-07-27-14', u'DBInstanceIdentifier': u'test-mo'}, 'url': u'https://rds.sa-east-1.amazonaws.com/', 'headers': {'User-Agent': 'aws-cli/1.11.36 Python/2.7.13 Linux/4.10.13-200.fc25.x86_64 botocore/1.4.93'}, 'context': {'client_region': 'sa-east-1', 'has_streaming_input': False, 'client_config': <botocore.config.Config object at 0x7f4c21b2a2d0>}, 'query_string': '', 'url_path': '/', 'method': u'POST'}
2017-07-27 11:39:13,480 - MainThread - botocore.hooks - DEBUG - Event request-created.rds.DownloadDBLogFilePortion: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f4c21b2a250>>
2017-07-27 11:39:13,480 - MainThread - botocore.auth - DEBUG - Calculating signature using v4 auth.
2017-07-27 11:39:13,480 - MainThread - botocore.auth - DEBUG - CanonicalRequest:
POST
/

host:rds.sa-east-1.amazonaws.com
x-amz-date:20170727T143913Z

host;x-amz-date
be5d3bcef11255151bed9990c6b4a52e2a54c6eeef26339a654f050cf9f977a6
2017-07-27 11:39:13,480 - MainThread - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20170727T143913Z
20170727/sa-east-1/rds/aws4_request
d7a64b7343323ec9b2be7834b7872f58cfbf5ecbc5d4b52bccc9ce7f2dde7d7a
2017-07-27 11:39:13,480 - MainThread - botocore.auth - DEBUG - Signature:
188e540e8dcc667f5d119ab5679d4b5edbf628a9cde17e9e3923ba7ffcc9f13f
2017-07-27 11:39:13,482 - MainThread - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [POST]>
2017-07-27 11:39:13,482 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): rds.sa-east-1.amazonaws.com
2017-07-27 11:39:13,964 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "POST / HTTP/1.1" 200 10541
2017-07-27 11:39:13,965 - MainThread - botocore.parsers - DEBUG - Response headers: {'x-amzn-requestid': '5c28b2c9-72d9-11e7-9958-ff47078c0460', 'vary': 'Accept-Encoding', 'content-length': '10541', 'content-type': 'text/xml', 'date': 'Thu, 27 Jul 2017 14:39:12 GMT'}
2017-07-27 11:39:13,966 - MainThread - botocore.parsers - DEBUG - Response body:
<DownloadDBLogFilePortionResponse xmlns="http://rds.amazonaws.com/doc/2014-10-31/">
  <DownloadDBLogFilePortionResult>
    <AdditionalDataPending>false</AdditionalDataPending>
    <LogFileData>2017-07-27 14:36:23 UTC::@:[3318]:LOG:  database system was shut down at 2017-02-10 19:28:25 UTC
2017-07-27 14:36:23 UTC::@:[3318]:LOG:  MultiXact member wraparound protections are now enabled
2017-07-27 14:36:23 UTC::@:[3316]:LOG:  database system is ready to accept connections
2017-07-27 14:36:23 UTC::@:[3322]:LOG:  autovacuum launcher started
...
2017-07-27 14:38:44 UTC:10.254.14.39(46798):[unknown]@[unknown]:[4713]:LOG:  connection received: host=10.254.14.39 port=46798
2017-07-27 14:38:44 UTC:10.254.14.39(46798):test@postgres:[4713]:LOG:  connection authorized: user=test database=postgres
2017-07-27 14:38:51 UTC:10.254.14.39(46798):test@postgres:[4713]:LOG:  duration: 5007.122 ms  statement: SELECT '????e??t';
</LogFileData>
    <Marker>15:9745</Marker>
  </DownloadDBLogFilePortionResult>
  <ResponseMetadata>
    <RequestId>5c28b2c9-72d9-11e7-9958-ff47078c0460</RequestId>
  </ResponseMetadata>
</DownloadDBLogFilePortionResponse>

2017-07-27 11:39:13,968 - MainThread - botocore.hooks - DEBUG - Event needs-retry.rds.DownloadDBLogFilePortion: calling handler <botocore.retryhandler.RetryHandler object at 0x7f4c21ba5990>
2017-07-27 11:39:13,968 - MainThread - botocore.retryhandler - DEBUG - No retry needed.
2017-07-27 11:39:13,968 - MainThread - botocore.paginate - DEBUG - Attempting to fall back to old starting token parser. For token: 0

Do you think it may be a problem in my terminal (I tried on different systems and all the same)? Does aws-cli have an option to save the file directly instead of relying on redirection?

[kyleknap]

Thanks for the debug logs. We are going to do more research into why this may be happening, but don't think it is an issue with the redirection as the question marks are showing up in the debug logs as well.

[kdaily]

@matheusoliveira,

Is this still an issue for you?

[github-actions]

Greetings! It looks like this issue hasn’t been active in longer than a week. We encourage you to check if this is still an issue in the latest release. Because it has been longer than a week since the last update on this, and in the absence of more information, we will be closing this issue soon. If you find that this is still a problem, please feel free to provide a comment or add an upvote to prevent automatic closure, or if the issue is already closed, please feel free to open a new one.