Module deployment issue - The JSON document is invalid.

[StephanBis]

OS version:
Windows 10 Pro x64 (1709) - Running in Azure

Docker version:
Client:
Version: 18.03.1-ce
API version: 1.37
Go version: go1.9.5
Git commit: 9ee9f40
Built: Thu Apr 26 07:12:48 2018
OS/Arch: windows/amd64
Experimental: false
Orchestrator: swarm

Server:
Engine:
Version: 18.03.1-ce
API version: 1.37 (minimum version 1.24)
Go version: go1.9.5
Git commit: 9ee9f40
Built: Thu Apr 26 07:21:42 2018
OS/Arch: windows/amd64
Experimental: false

IoT Edge version:
1.0-preview

Issue description:
I'm following the quickstart guide for setting up an IoT Edge and how to deploy a custom C# module. The EdgeAgent, EdgeHub and TempSensor are running as they should. But when I deploy the custom module named "filterModule", I get the exception: "Docker.DotNet.DockerApiException: Docker API responded with status code=InternalServerError, response={"message":"container a9626f22c450983c8ff99d8a4dcf2f2db1e7aab43499935f89b321687ee560e4 encountered an error during Start: failure in a Windows system call: The JSON document is invalid. (0xc037010d"
In the IoT Edge device manager in Azure I get the following runtime status and exit code for the "filterModule": Backoff - Exit code: 128.

Full stack trace:

at Docker.DotNet.DockerClient.HandleIfErrorResponse(HttpStatusCode statusCode, String responseBody, IEnumerable1 handlers) at Docker.DotNet.DockerClient.<MakeRequestAsync>d__45.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Docker.DotNet.ContainerOperations.<StartContainerAsync>d__9.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.<ExecuteAsync>d__6.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 66 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.<ExecuteAsync>d__5.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 36 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.<ExecuteAsync>d__6.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 66 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.<ExecuteAsync>d__7.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 86 --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.<>c.<ExecuteAsync>b__7_0(List1 f) in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 116
at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.d__7.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 117
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.d__10.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 132
---> (Inner Exception #0) Docker.DotNet.DockerApiException: Docker API responded with status code=InternalServerError, response={"message":"container a9626f22c450983c8ff99d8a4dcf2f2db1e7aab43499935f89b321687ee560e4 encountered an error during Start: failure in a Windows system call: The JSON document is invalid. (0xc037010d)"}
at Docker.DotNet.DockerClient.HandleIfErrorResponse(HttpStatusCode statusCode, String responseBody, IEnumerable`1 handlers)
at Docker.DotNet.DockerClient.d__45.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Docker.DotNet.ContainerOperations.d__9.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.d__6.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 66
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.d__5.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 36
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.d__6.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 66
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.d__7.MoveNext() in /opt/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 86<---
2018-05-24 19:10:11.821 +00:00 [WRN] - Agent reconcile concluded with errors.
System.AggregateException: One or more errors occurred. (Docker API responded with status code=InternalServerError, response={"message":"container a9626f22c450983c8ff99d8a4dcf2f2db1e7aab43499935f89b321687ee560e4 encountered an error during Start: failure in a Windows system call: The JSON document is invalid. (0xc037010d)"}
) ---> Docker.DotNet.DockerApiException: Docker API responded with status code=InternalServerError, response={"message":"container a9626f22c450983c8ff99d8a4dcf2f2db1e7aab43499935f89b321687ee560e4 encountered an error during Start: failure in a Windows system call: The JSON document is invalid. (0xc037010d)"}

Things I've already tried:

• Restarted VM
• Restarted Docker
• Reinstalled Docker
• Reinstalled IoT Edge Runtime (as stated in the quickstart) and removed all remaining Docker images/containers.
• Rechecked the setup procedure (followed the quickstart's exact steps)
• Made sure custom C# module is building locally and redeployed to Azure Container Repository just to be sure.

Can anyone point me in the right direction? Or is this a bug in the agent itself? Thank you.

[darobs]

Hello @StephanBis

This looks like it's a duplicate of #611, which was a Azure Portal issue. The deployment schema was changed at the portal, but not on the Edge deployment, which meant we failed to parse the new deployment.

Please update your deployment on the Azure Portal, this should regenerate the Edge deployment and the Edge runtime will restart.

I'm closing this issue, but if you continue to have trouble, please reopen or open an new issue.

[StephanBis]

Thank you for your answer @darobs . I created a new Edge deployment and let it deploy to the Edge, however the same exception gets thrown. I also made sure that the custom modules were removed before I created the new deployment, just to be sure.

[StephanBis]

@darobs friendly bump.

[darobs]

When you get to the final deployment description in the deployment wizard, do you see each module has a description with each of these fields?

        "modules": {
          "<module name>": {
            "version": "1.0",
            "type": "docker",
            "status": "running",
            "restartPolicy": "always",
            "settings": {
              "image": "<Image>",
              "createOptions": "{}"
            }

Specifically, the portal issue was the missing "version" field.

[StephanBis]

Yes, both my modules have the "version" field.

"modules": {
"tempSensor": {
"version": "1.0",
"type": "docker",
"status": "running",
"restartPolicy": "always",
"settings": {
"image": "microsoft/azureiotedge-simulated-temperature-sensor:1.0-preview",
"createOptions": "{}"
}
},
"filterModule": {
"version": "1.0",
"type": "docker",
"status": "running",
"restartPolicy": "always",
"settings": {
"image": "{mycontainerregistry}.azurecr.io/filtermodule:0.0.1-windows-amd64",
"createOptions": "{}"
}
}
}

EDIT: I've completely reinstalled IoT Edge on the VM and created a new IoT Edge device in the Azure Portal. Also created a new Docker image of the "filterModule" and pushed it as 0.0.2 to the container registry. Created a new deployment and let it deploy. Outcome: same exception occuring with the "filterModule" and now $edgeHub keeps hanging on the "Pending Modification" deployment status.

[StephanBis]

Another update: used Visual Studio Code to generate a new sample module and deployed that as a completely new module. And again we get the same exception when it tries to deploy..! I don't see any new comments on #611, is the problem completely solved now?

[StephanBis]

@darobs I'm still experiencing this issue.. could you please re-open this issue and investigate with me?

[darobs]

Thank you for your patience, @StephanBis.

OK, this filter module is coming from this example? In the C Sharp code, the most likely place you'd run into an uncaught exception in the example code is the call to GetTwinAsync(). Would you please check the filterModule's twin to see if it has a valid JSON in it?

The other places in that code that might fail a JSON parse are less likely (since the exceptions are caught)
but are:

1. Twin updates fail
2. an incoming message is improperly formatted.

If you drop the filterModule from the deployment and set the routes back to one rule, "FROM /* INTO $upstream", do you see well formatted messages like this?

{
  "machine" : {
    "temperature" : 0.0,
    "pressure" : 0.0
  },
  "ambient" : {
    "temperature" : 0.0,
     "humidity" : 0.0
  },
  "timeCreated" : "<UTC datetime>"
}

[StephanBis]

Thank you for your reply @darobs! The twin contains valid JSON and messages sent from the TempSensor module are also OK.
For debugging purposes I tried publishing a completely empty module without any send/receive functionality. This one also results in "backoff - Exit code: 128" with the log filled with error messages once again stating "The JSON document is invalid.". Also removed the repository from the container registry and started again with the tutorial... same result as before.