Aws-cdk: Python JSONDecodeError on CDK deploy

Created on 16 Sep 2019 · 12Comments · Source: aws/aws-cdk

:bug: Bug Report

What is the problem?

When attempting to do a cdk deploy from a Stack created in python, i am getting a JSONDecodeError (shown a little further down). This is occurring while running on a self-hosted Azure DevOps build agent. The exception only occurs when running this build agent in an ECS EC2 hosted container on the same account where we are attempting to deploy, however if we run the build agent container on a local dev machine, it is able to run the cdk deploy without any difficulty. This leads us to believe that the deployment process is having some kind of access issue connecting to a specific AWS API, or that the returned JSON response from one of these APIs is missing or invalid. We have not determined which construct is causing the issue at this point, but were asked by AWS Support to go ahead and submit this as an issue on this github project.

The below exception, based on the verbose logging we are viewing, is occurring right before the deploy process is identifying the stack dependencies and starting deployment.

2019-09-13T17:08:11.6233423Z Traceback (most recent call last):
2019-09-13T17:08:11.6271925Z   File "portal_app.py", line 26, in <module>
2019-09-13T17:08:11.6272102Z     app.synth()
2019-09-13T17:08:11.6294644Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/aws_cdk/core/__init__.py", line 2840, in synth
2019-09-13T17:08:11.6294812Z     return jsii.invoke(self, "synth", [])
2019-09-13T17:08:11.6295230Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/__init__.py", line 104, in wrapped
2019-09-13T17:08:11.6295373Z     return _recursize_dereference(kernel, fn(kernel, *args, **kwargs))
2019-09-13T17:08:11.6295769Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/__init__.py", line 267, in invoke
2019-09-13T17:08:11.6295995Z     args=_make_reference_for_native(self, args),
2019-09-13T17:08:11.6296406Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 346, in invoke
2019-09-13T17:08:11.6296538Z     return self._process.send(request, InvokeResponse)
2019-09-13T17:08:11.6296931Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 308, in send
2019-09-13T17:08:11.6297059Z     self._next_message(), _ProcessResponse_R
2019-09-13T17:08:11.6297512Z   File "/var/vsts/0e0e1478c340-agent/r1/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 259, in _next_message
2019-09-13T17:08:11.6297952Z     return json.loads(self._process.stdout.readline(), object_hook=ohook)
2019-09-13T17:08:11.6298075Z   File "/usr/local/lib/python3.6/json/__init__.py", line 367, in loads
2019-09-13T17:08:11.6298158Z     return cls(**kw).decode(s)
2019-09-13T17:08:11.6298258Z   File "/usr/local/lib/python3.6/json/decoder.py", line 339, in decode
2019-09-13T17:08:11.6298340Z     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2019-09-13T17:08:11.6298425Z   File "/usr/local/lib/python3.6/json/decoder.py", line 357, in raw_decode
2019-09-13T17:08:11.6298533Z     raise JSONDecodeError("Expecting value", s, err.value) from None
2019-09-13T17:08:11.6298620Z json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2019-09-13T17:08:11.6339409Z Subprocess exited with error 1
2019-09-13T17:08:11.7034597Z Error: Subprocess exited with error 1
2019-09-13T17:08:11.7036332Z     at ChildProcess.proc.on.code (/usr/local/lib/node_modules/aws-cdk/lib/api/cxapp/exec.ts:110:23)
2019-09-13T17:08:11.7036808Z     at ChildProcess.emit (events.js:198:13)
2019-09-13T17:08:11.7037209Z     at ChildProcess.EventEmitter.emit (domain.js:448:20)
2019-09-13T17:08:11.7037597Z     at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)

Reproduction Steps

Working on finding a more simple stack that can reproduce this same issue. Currently cannot share the full stack I am working on.

Verbose Log

Working on removing confidential information.

Environment

CDK CLI Version: CDK toolkit version: 1.8.0 (build 5244f97)
Module Version: 1.8.0
OS: Ubuntu 16.04
Language: Python

@aws-cdcore bug languagpython needs-reproduction p1

Source

imonthercks

All 12 comments

Please run this with JSII_DEBUG=1 and share what you can from the additional logging to stderr with us, especially the last part leading up to the error.

rix0rrr on 17 Sep 2019

Thanks for the hint on the JSII_DEBUG environment variable. That could come in really handy in debugging future issues. It looks like it is breaking on a synth method call? The log has about 15K lines, so I grabbed the debug logging for the last couple of method calls. If more is needed, or if there is anything specific I can scan for, let me know. I am hesitant to post the whole thing without giving a scan to see if there is anything sensitive. Thanks! See below.

2019-09-17T22:46:42.3219777Z > {"objref":{"$jsii.byref":"@aws-cdk/aws-dynamodb.Table@10124"},"method":"grant","args":[{"$jsii.byref":"@aws-cdk/aws-iam.Role@10086"},"dynamodb:DescribeTable"],"api":"invoke"}
2019-09-17T22:46:42.3220325Z [jsii-kernel] invoke { '$jsii.byref': '@aws-cdk/aws-dynamodb.Table@10124' } grant [ { '$jsii.byref': '@aws-cdk/aws-iam.Role@10086' },
2019-09-17T22:46:42.3220770Z   'dynamodb:DescribeTable' ]
2019-09-17T22:46:42.3221388Z [jsii-kernel] toSandbox { '$jsii.byref': '@aws-cdk/aws-iam.Role@10086' } [{"serializationClass":"RefType","typeRef":{"docs":{"summary":"The principal (no-op if undefined)."},"name":"grantee","type":{"fqn":"@aws-cdk/aws-iam.IGrantable"}}}]
2019-09-17T22:46:42.3222091Z [jsii-kernel] toSandbox dynamodb:DescribeTable [{"serializationClass":"Scalar","typeRef":{"docs":{"summary":"The set of actions to allow (i.e. \"dynamodb:PutItem\", \"dynamodb:GetItem\", ...)."},"name":"actions","type":{"primitive":"string"},"variadic":true}}]
2019-09-17T22:46:42.3245883Z [jsii-kernel] fromSandbox Grant {
2019-09-17T22:46:42.3246240Z   options:
2019-09-17T22:46:42.3246407Z    { grantee:
2019-09-17T22:46:42.3246516Z       Role {
2019-09-17T22:46:42.3246619Z         node: [ConstructNode],
2019-09-17T22:46:42.3246787Z         stack: [Stack],
2019-09-17T22:46:42.3246902Z         _physicalName: undefined,
2019-09-17T22:46:42.3247034Z         _allowCrossEnvironment: false,
2019-09-17T22:46:42.3247391Z         physicalName: '${Token[TOKEN.273]}',
2019-09-17T22:46:42.3247512Z         grantPrincipal: [Circular],
2019-09-17T22:46:42.3247941Z         assumeRoleAction: 'sts:AssumeRole',
2019-09-17T22:46:42.3248206Z         managedPolicies: [],
2019-09-17T22:46:42.3248329Z         attachedPolicies: [AttachedPolicies],
2019-09-17T22:46:42.3248439Z         assumeRolePolicy: [PolicyDocument],
2019-09-17T22:46:42.3248957Z         permissionsBoundary: undefined,
2019-09-17T22:46:42.3249434Z         roleId: '${Token[TOKEN.278]}',
2019-09-17T22:46:42.3249700Z         roleArn: '${Token[TOKEN.279]}',
2019-09-17T22:46:42.3250177Z         roleName: '${Token[TOKEN.281]}',
2019-09-17T22:46:42.3250429Z         policyFragment: [PrincipalPolicyFragment],
2019-09-17T22:46:42.3250553Z         defaultPolicy: [Policy],
2019-09-17T22:46:42.3250881Z         [Symbol(@aws-cdk/core.DependableTrait)]: [Object],
2019-09-17T22:46:42.3251346Z         [Symbol($__jsii__objid__$)]: '@aws-cdk/aws-iam.Role@10086' },
2019-09-17T22:46:42.3251647Z      actions: [ 'dynamodb:DescribeTable' ],
2019-09-17T22:46:42.3252103Z      resourceArns: [ '${Token[TOKEN.480]}', '${Token[TOKEN.494]}' ],
2019-09-17T22:46:42.3252389Z      scope:
2019-09-17T22:46:42.3990358Z       Table {
2019-09-17T22:46:42.3996805Z         node: [ConstructNode],
2019-09-17T22:46:42.3997108Z         stack: [Stack],
2019-09-17T22:46:42.3997828Z         _physicalName: 'dev-KES_UserRole',
2019-09-17T22:46:42.3998284Z         _allowCrossEnvironment: true,
2019-09-17T22:46:42.3998835Z         physicalName: 'dev-KES_UserRole',
2019-09-17T22:46:42.3999111Z         keySchema: [Array],
2019-09-17T22:46:42.3999228Z         attributeDefinitions: [Array],
2019-09-17T22:46:42.3999333Z         globalSecondaryIndexes: [],
2019-09-17T22:46:42.3999542Z         localSecondaryIndexes: [],
2019-09-17T22:46:42.3999682Z         secondaryIndexNames: [],
2019-09-17T22:46:42.3999767Z         nonKeyAttributes: [],
2019-09-17T22:46:42.3999966Z         tableScaling: {},
2019-09-17T22:46:42.4000106Z         indexScaling: Map {},
2019-09-17T22:46:42.4000389Z         billingMode: 'PROVISIONED',
2019-09-17T22:46:42.4000497Z         table: [CfnTable],
2019-09-17T22:46:42.4000922Z         tableArn: '${Token[TOKEN.480]}',
2019-09-17T22:46:42.4001248Z         tableName: '${Token[TOKEN.482]}',
2019-09-17T22:46:42.4001337Z         tableStreamArn: undefined,
2019-09-17T22:46:42.4001418Z         scalingRole: [MutableImport],
2019-09-17T22:46:42.4001692Z         tablePartitionKey: [Object],
2019-09-17T22:46:42.4002094Z         [Symbol(@aws-cdk/core.DependableTrait)]: [Object],
2019-09-17T22:46:42.4002466Z         [Symbol($__jsii__objid__$)]: '@aws-cdk/aws-dynamodb.Table@10124' } },
2019-09-17T22:46:42.4002719Z   principalStatement:
2019-09-17T22:46:42.4002864Z    PolicyStatement {
2019-09-17T22:46:42.4003169Z      action: [ 'dynamodb:DescribeTable' ],
2019-09-17T22:46:42.4003411Z      notAction: [],
2019-09-17T22:46:42.4003521Z      principal: {},
2019-09-17T22:46:42.4003871Z      resource: [ '${Token[TOKEN.480]}', '${Token[TOKEN.494]}' ],
2019-09-17T22:46:42.4004094Z      notResource: [],
2019-09-17T22:46:42.4004234Z      condition: {},
2019-09-17T22:46:42.4004520Z      effect: 'Allow' },
2019-09-17T22:46:42.4004870Z   resourceStatement: undefined } [{"serializationClass":"RefType","typeRef":{"type":{"fqn":"@aws-cdk/aws-iam.Grant"}}}]
2019-09-17T22:46:42.4005349Z [jsii-kernel] invoke result { '$jsii.byref': '@aws-cdk/aws-iam.Grant@10126' }
2019-09-17T22:46:42.4005885Z < {"ok":{"result":{"$jsii.byref":"@aws-cdk/aws-iam.Grant@10126"}}}
2019-09-17T22:46:42.4006379Z > {"objref":{"$jsii.byref":"@aws-cdk/core.App@10000"},"method":"synth","args":[],"api":"invoke"}
2019-09-17T22:46:42.4006932Z [jsii-kernel] invoke { '$jsii.byref': '@aws-cdk/core.App@10000' } synth []
2019-09-17T22:46:48.3743822Z Traceback (most recent call last):
2019-09-17T22:46:48.3744554Z   File "portal_app.py", line 26, in <module>
2019-09-17T22:46:48.3744667Z     app.synth()
2019-09-17T22:46:48.4004855Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/aws_cdk/core/__init__.py", line 2840, in synth
2019-09-17T22:46:48.4005171Z     return jsii.invoke(self, "synth", [])
2019-09-17T22:46:48.4005661Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/__init__.py", line 104, in wrapped
2019-09-17T22:46:48.4006159Z     return _recursize_dereference(kernel, fn(kernel, *args, **kwargs))
2019-09-17T22:46:48.4006644Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/__init__.py", line 267, in invoke
2019-09-17T22:46:48.4006758Z     args=_make_reference_for_native(self, args),
2019-09-17T22:46:48.4007181Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 346, in invoke
2019-09-17T22:46:48.4007311Z     return self._process.send(request, InvokeResponse)
2019-09-17T22:46:48.4007709Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 308, in send
2019-09-17T22:46:48.4007835Z     self._next_message(), _ProcessResponse_R
2019-09-17T22:46:48.4008241Z   File "/var/vsts/0122e5dac78b-agent/r2/a/_KES_Portal/DockerBuildArtifact/Infrastructure/kes-portal-cdk/.env/lib/python3.6/site-packages/jsii/_kernel/providers/process.py", line 259, in _next_message
2019-09-17T22:46:48.4008527Z     return json.loads(self._process.stdout.readline(), object_hook=ohook)
2019-09-17T22:46:48.4008619Z   File "/usr/local/lib/python3.6/json/__init__.py", line 367, in loads
2019-09-17T22:46:48.4008719Z     return cls(**kw).decode(s)
2019-09-17T22:46:48.4008802Z   File "/usr/local/lib/python3.6/json/decoder.py", line 339, in decode
2019-09-17T22:46:48.4008885Z     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2019-09-17T22:46:48.4008991Z   File "/usr/local/lib/python3.6/json/decoder.py", line 357, in raw_decode
2019-09-17T22:46:48.4009080Z     raise JSONDecodeError("Expecting value", s, err.value) from None
2019-09-17T22:46:48.4009189Z json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2019-09-17T22:46:48.5092873Z Subprocess exited with error 1
2019-09-17T22:46:48.5511784Z Error: Subprocess exited with error 1
2019-09-17T22:46:48.5513162Z     at ChildProcess.proc.on.code (/usr/local/lib/node_modules/aws-cdk/lib/api/cxapp/exec.ts:110:23)
2019-09-17T22:46:48.5513352Z     at ChildProcess.emit (events.js:198:13)
2019-09-17T22:46:48.5513473Z     at ChildProcess.EventEmitter.emit (domain.js:448:20)
2019-09-17T22:46:48.5513563Z     at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)

imonthercks on 18 Sep 2019

It now looks like something changed in our stack that this is now working. I will try to get my head around the changes that were made between the last known failing revision and the first known successful, and let you know. Perhaps that can help narrow it down. If so, I will try to provide a stack that will reproduce the error.

Confirmed that previous revision still does cause the error.

imonthercks on 18 Sep 2019

Oh well, apparently logging happens AFTER trying to JSON-decode, so this log wouldn't show the problem anyway :(

rix0rrr on 18 Sep 2019

It seems to come down to NodeJS serializing some JSON that Python won't deserialize. My money is on unicode characters and character encodings mucking something up.

Were you using any of those?

rix0rrr on 18 Sep 2019

@rix0rrr, to my knowledge we were not using any unicode characters or any characters that might have tripped up Python when deserializing JSON, but I will take a look through the stack to make sure. I'll update as I discover more about when and where this occurs.

imonthercks on 18 Sep 2019

@imonthercks - it would be super helpful if you were able to trim your application down to the minimum code that triggers the issue, so we can try to reproduce that for troubleshooting purposes.

Meanwhile, we should still enhance the deserialization error in the jsii runtime so that we get more insight on exactly what broke the parser.

RomainMuller on 20 Sep 2019

@RomainMuller, I have seen the issue occur again, so I am going to try to get this pared down to a small reproducible stack. May not happen today, but I'll get it to you as soon as I can.

imonthercks on 20 Sep 2019

👍1

I can reproduce this if using node-13.x. With node-10.x it works fine. Commands to reproduce on Ubuntu 18

sudo pip install aws-cdk.core
apt-get install python3-venv

curl "https://s3.amazonaws.com/aws-cli/awscli-bundle.zip" -o "awscli-bundle.zip"
unzip awscli-bundle.zip
sudo python3 ./awscli-bundle/install -i /usr/local/aws -b /usr/local/bin/aws

curl -sL https://deb.nodesource.com/setup_13.x | sudo -E bash -
sudo apt-get install -y nodejs

sudo npm install -g aws-cdk

cdk init --language python
source .env/bin/activate
cdk ls