How can I make debug statements visible in the sandbox logs?

[georg]

I added some debug (...) statements to my models in order to understand the logic being executed, but they don’t show up in the sandbox logs. How can I make them visible?

[cocreature]

Great question!
To make trace statements visible you need to set the log level of daml.tracelog to DEBUG. There are two ways to to this:

Show all debug logs

You can run daml sandbox --log-level=DEBUG and it will show you all debug logs which includes the daml.tracelog logs. However, it will show you much much more than that so this is probably not what you want.

Use a custom logback.xml

Instead of showing all debug statements you can select daml.tracelog individually. This requires that you write a custom logback configuration file. You can find the default logback config used by daml sandbox at $HOME/.daml/sdk/$YOUR_SDK_VERSION/daml-sdk/sandbox-logback.xml. Start by copying that to your project directory as logback.xml. Next modify it to change the end such that it looks like this:

    <logger name="daml.tracelog" level="DEBUG" />
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="ASYNC"/>
    </root>
</configuration>

Now you have to get sandbox to pick up this modified file. There are two options for this:

First you can set the _JAVA_OPTIONS environment variable via

export _JAVA_OPTIONS="-Dlogback.configurationFile=./logback.xml"

That will then be picked up by all JVM processes. Note that it is important to use _JAVA_OPTIONS and not JAVA_TOOL_OPTIONS. The former takes precedence over CLI arguments while the latter doesn’t so you cannot use it to override the logback config passed by the assistant. It also seems to be important to use ./logback.xml or an absolute path instead of logback.xml.

The other option is to sidestep the assistant completely. Note that this relies on details of the SDK tarball which are not guaranteed to be stable across versions. The JAR invoked by daml sandbox is located at ~/.daml/sdk/$YOUR_SDK_VERSION/daml-sdk/daml-sdk.jar. You can invoke that directly via java -jar. Since there is a single JAR for the whole SDK you have to pass sandbox as the first argument. Putting things together, you can launch sandbox with a given logback config as follows:

java -Dlogback.configurationFile=./logback.xml -jar ~/.daml/sdk/1.1.1/daml-sdk/daml-sdk.jar sandbox .daml/dist/foobar-0.0.1.dar

Sidenote

The log statement will be printed whenever it is evaluated. In thew new sandbox, this seems to happen twice (presumably once for validation) so you see the log statement twice as well. In Sandbox classic, it is only printed once.

[georg]

Super comprehensive response @cocreature! Thanks for taking the time to write this up.

[var]

Another use case which @cocreature helped me clarify and resolve. I wanted to document here, in case someone else is looking for this.

I am using docker/docker-compose to spin up sandbox and needed to pass in JMX config to the java process that daml sandbox-classic spins up.

  sandbox:
    image: digitalasset/daml-sdk:1.2.0
    healthcheck:
      test: ["CMD", "sh", "-c", "(netstat -tulpn | grep 0.0.0.0:6865 | grep LISTEN) || exit 1"]
      interval: 2s
      start_period: 10s
      timeout: 5s
      retries: 20
    environment:
      - _JAVA_OPTIONS="-Djava.rmi.server.hostname=sandbox -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.rmi.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.ssl.need.client.auth=false"
    entrypoint:
      - daml
      - sandbox-classic
      - --address
      - 0.0.0.0

But noticed that the JMX port was not being opened up. After consultation with @cocreature he pointed out that the environment variable passed in has to be quoted in entirety for it to work. So the correct way of writing it would be:

environment:
      - "_JAVA_OPTIONS=-Djava.rmi.server.hostname=sandbox -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.rmi.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.ssl.need.client.auth=false"

Quoting the entire environment variable fixed the issue, and JMX port worked!

Just reading up on _JAVA_OPTIONS vs JAVA_TOOL_OPTIONS, in my particular use case, JAVA_TOOL_OPTIONS would work because there is no need to override the logging config set by daml assistant.

Some references:

• https://stackoverflow.com/a/40736904
• https://bugs.openjdk.java.net/browse/JDK-4971166
• https://stackoverflow.com/a/30305597

[Gary_Verhaegen]

I believe it would also work with no quotes at all. This is a YAML parsing issue (or feature, I guess). YAML conceptually parses down to JSON, so here is an illustration using JSON:

- a=1
- "b=2"
- c="3"

parses to the JSON equivalent:

["a=1", "b=2", "c=\"3\""]

i.e. having no quotes at all is equivalent to implicitly having quotes around everything, whereas quotes that appear in the middle of a YAML string are taken to be part of the string.

The env var passed through docker-compose are not further evaluated by Bash, so - c="3" in YAML is the equivalent of

docker run -e 'c="3"' ...

which sets the env var c in the container to "3", and not, as one could have expected

docker run -e c="3" ...

where the quotes would be parsed and removed by Bash and thus set the env var c in the container to 3.

[anthony]

Welcome to the forum @var and thank you for going out of your way to share an issue that might be useful for others.

Did you encounter any error message when the port wasn’t opening up? If so pasting it into your post might help other people find it in the future.

[var]

@Gary_Verhaegen You are correct, it works without the quotes too:

environment:
      - JAVA_TOOL_OPTIONS=-Djava.rmi.server.hostname=sandbox -Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.rmi.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.ssl.need.client.auth=false

I was thinking because of the spaces between the values it had to be quoted.

Thanks!

[var]

@anthony, thanks for pointing that out.

So I did not get any error from the daml sandbox. In the daml container I was looking for the port 9999 to be enabled and listening on all inerfaces i.e. 0.0.0.0, and it was missing. The JMX exporter I was running would then complain that it could not connect to port 9999 but that was a separate container.

So the error was, nothing listening on port 9999:

$ netstat -tanlp | grep 9999
$

If the JMX port was correctly opened it should look like:

$ netstat -tanlp | grep 9999
tcp        0      0 0.0.0.0:9999            0.0.0.0:*               LISTEN      27/java
$

For anyone else debugging these things in docker containers, 0.0.0.0 is important within a docker container. If the port was opened on the loopback interface which is 127.0.0.1, then any process outside of the particular docker container trying to connect won’t succeed. Because 127.0.0.1 is not connected to the bridge that allows traffic from within a container to go outside of the container, there is a eth0 interface within a docker container that allows this to happen. Recommendation is to bind to the 0.0.0.0 i.e., all interfaces.

Thanks!

[Frankie]

I was going through the different types of logging DAML can do. Here is what I found so far on sandbox

debug → log level DEBUG
trace → log level DEBUG
assert → log level ERROR
error → log level ERROR
abort → log level ERROR

However the ERROR log are wrapped inside INFO. You won’t see them unless you do --log-level INFO. Is that correct? It is something like this…

INFO: Submission of command rejected: INVALID_ARGUMENT: Command interpretation error in LF-DAMLe: Interpretation error: Error: User abort: [2020-07-16T01:19:33.140Z] - assert gone bad. Details: Last location: [DA.Internal.Assert:19], partial transaction: . (context: {commandId=e38989bb2a00211f, parties=[Bob]})

[cocreature]

assert, error and abort all have log-level INFO not ERROR. The reason for this is that a failed assertion (or error and abort) isn’t an error for the ledger. It could just be some validation logic and the user submitted a command that didn’t pass validation. So from the ledger’s POV nothing went wrong.

[mesch]

@cocreature

–log-level=DEBUG

Is it correct that this flag does not exist in daml sandbox in canton anymore?

[a_putkov]

@mesch
Correct. With Canton you have more granular logging options. See daml sandbox --canton-help for details of the command line parameters available.
A housekeeping note: when asking a new question, please always start a new thread. If you need to reference an existing thread, include the link in your post.