Unable to retrieve Container logs with invalid utf-8 sequences (panic)

aureq commented 5 months ago

Describe what happened

(Related to this Slack thread)

While investigating the thread mentioned above, I create a basic container printing garbage utf-8 sequences. While I couldn't get the same error message as our customer, I found 4 occurrences of a crash when calling the datasource Docker.GetLogs().

The app consists of:

A C# Pulumi app
A basic `Dockerfile
A Bash shell script echoing the sequences

Sample program

Program.cs

using System;
using System.Collections.Generic;
using Pulumi;
using Pulumi.Docker;

return await Deployment.RunAsync(() =>
{
    var imageName = "my-sample-app";

    var MyDockerProvider = new Pulumi.Docker.Provider("docker-provider", new ProviderArgs
    {
        CertPath = "/home/aureq/.docker",
    });

    var MyDockerImage = new Image("docker-image", new ImageArgs
    {
        Build = new Pulumi.Docker.Inputs.DockerBuildArgs
        {
            Context = ".",
            Dockerfile = "Dockerfile",
            Platform = "linux/amd64",
        },
        ImageName = $"{imageName}:v1.0.0",
        SkipPush = true,

    }, new CustomResourceOptions
    {
        Provider = MyDockerProvider,
    });

    var MyDockerContainer = new Pulumi.Docker.Container("docker-container", new ContainerArgs
    {
        Name = imageName,
        Image = MyDockerImage.Id,
        Attach = true,
        Logs = true,
        MustRun = false,

    }, new CustomResourceOptions
    {
        Provider = MyDockerProvider,
    });

    var MyDockerContainerLogs = Pulumi.Output.All(MyDockerContainer.Name, MyDockerContainer.Id).Apply(values =>
    {
        var containerName = values[0];
        var containerId = values[1];

        var containerLogs = Pulumi.Docker.GetLogs.InvokeAsync(new GetLogsArgs
        {
            Name = containerName,
            Follow = true,
            ShowStdout = true,
            ShowStderr = true,
        }, new InvokeOptions
        {
            Provider = MyDockerProvider,
            Parent = MyDockerContainer,
        });
        System.Console.WriteLine($"Name: {containerName}, Id: {containerId}");
        return containerLogs;
    });

    // Export outputs here
    return new Dictionary<string, object?>
    {
        // ["MyDockerContainerLogs"] = MyDockerContainerLogs.Apply(logList => logList.LogsListStrings),
        ["MyDockerContainer"] = MyDockerContainer.ContainerLogs
    };
});

Dockerfile

FROM debian:latest

COPY app/entrypoint.sh /
RUN chmod 0755 /entrypoint.sh

CMD ["/entrypoint.sh"]

app/entrypoint.sh

#!/bin/bash

generate_invalid_utf8() {
    # Array of invalid UTF-8 byte sequences
    invalid_sequences=(
        "a"                         # valid ASCII
        "\xc3\xb1"                  # Valid 2 Octet Sequence
        "\xc3\x28"                  # Invalid 2 Octet Sequence
        "\xa0\xa1"                  # Invalid Sequence Identifier
        "\xe2\x28\xa1"              # Valid 3 Octet Sequence
        "\xe2\x28\xa1"              # Invalid 3 Octet Sequence (in 2nd Octet)
        "\xe2\x82\x28"              # Invalid 3 Octet Sequence (in 3rd Octet)
        "\xf0\x90\x8c\xbc"          # Valid 4 Octet Sequence
        "\xf0\x28\x8c\xbc"          # Invalid 4 Octet Sequence (in 2nd Octet)
        "\xf0\x90\x28\xbc"          # Invalid 4 Octet Sequence (in 3rd Octet)
        "\xf0\x28\x8c\x28"          # Invalid 4 Octet Sequence (in 4th Octet)
        "\xf8\xa1\xa1\xa1\xa1"      # Valid 5 Octet Sequence (but not Unicode!)
        "\xfc\xa1\xa1\xa1\xa1\xa1"  # Valid 6 Octet Sequence (but not Unicode!)
        "\xF0\xA4\xAD\xA2"          # Invalid Sequence
        "\xC0\xAF"                  # Overlong encoding of '/'
        # "\xE0\x80\xAF"              # Overlong encoding of '/'                      # crash 1: crash docker:index/getLogs:getLogs
        "\xF0\x80\x80\xAF"          # Overlong encoding of '/'
        "\xF8\x80\x80\x80\xAF"      # Invalid 5-byte sequence
        "\xFC\x80\x80\x80\x80\xAF"  # Invalid 6-byte sequence
        "\xC1\xBF"                  # Overlong encoding of '?'
        # "\xE0\x9F\xBF"              # Overlong encoding of '?'                      # crash 2: crash docker:index/getLogs:getLogs
        "\xF0\x8F\xBF\xBF"          # Overlong encoding of '?'
        # "\xED\xA0\x80"              # Surrogate half (high)                         # crash 3: crash docker:index/getLogs:getLogs
        # "\xED\xBF\xBF"              # Surrogate half (low)                          # crash 4: crash docker:index/getLogs:getLogs
        "\xF5\x90\x80\x80"          # Invalid code point (greater than U+10FFFF)
        "\x80"                      # Lone continuation byte
        "\xC2"                      # Start byte without continuation
        "\xE1\x80"                  # Two-byte start without continuation
        # "\xF1\x80\x80"              # Three-byte start without continuation         # crash 5: crash docker:index/getLogs:getLogs
    )

    echo "Generating invalid UTF-8 sequences:"

    # Iterate over the array and display each invalid sequence
    for seq in "${invalid_sequences[@]}"; do
        echo -e "$seq"
    done
}

generate_invalid_utf8

Log output

After a close look, the 5 different test cases all generate the same crash.

    Name: my-sample-app, Id: 2dbe29309f6e9934c873a28076f7fdd26aa2692a3e963cbde2c38633af67f403

    panic: runtime error: slice bounds out of range [8:7]
    goroutine 142 [running]:
    github.com/terraform-providers/terraform-provider-docker/internal/provider.dataSourceDockerLogsRead({0x194d2d0, 0xc0002b2d20}, 0x0?, {0x13a6560?, 0xc0006da310?})
        /home/runner/work/pulumi-docker/pulumi-docker/upstream/internal/provider/data_source_docker_logs.go:118 +0x838
    github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema.(*Resource).read(0xc0007bf5e0, {0x194d228, 0xc0009e1470}, 0xd?, {0x13a6560, 0xc0006da310})
        /home/runner/go/pkg/mod/github.com/pulumi/terraform-plugin-sdk/v2@v2.0.0-20240520223432-0c0bf0d65f10/helper/schema/resource.go:795 +0x11b
    github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema.(*Resource).ReadDataApply(0xc0007bf5e0, {0x194d228, 0xc0009e1470}, 0xc000711600, {0x13a6560, 0xc0006da310})
        /home/runner/go/pkg/mod/github.com/pulumi/terraform-plugin-sdk/v2@v2.0.0-20240520223432-0c0bf0d65f10/helper/schema/resource.go:1015 +0x149
    github.com/pulumi/pulumi-terraform-bridge/v3/pkg/tfshim/sdk-v2.v2Provider.ReadDataApply({0xc00068c720?, {0x0?, 0xc000d07330?, 0x12c3afa?}}, {0x194d228, 0xc0009e1470}, {0x16cdefa, 0xb}, {0x1951100, 0xc000711600})
        /home/runner/go/pkg/mod/github.com/pulumi/pulumi-terraform-bridge/v3@v3.83.0/pkg/tfshim/sdk-v2/provider.go:197 +0xcb
    github.com/pulumi/pulumi-terraform-bridge/v3/pkg/tfbridge.(*Provider).Invoke(0xc0003f7300, {0x194d228?, 0xc0009e1110?}, 0xc000154040)
        /home/runner/go/pkg/mod/github.com/pulumi/pulumi-terraform-bridge/v3@v3.83.0/pkg/tfbridge/provider.go:1564 +0xb4f
    github.com/pulumi/pulumi-docker/provider/v4.dockerHybridProvider.Invoke({{}, {0x24b7f00, 0x29922, 0x29922}, {0x19327f8, 0x6}, {0x195fc00, 0xc0003f7300}, {0x195fa90, 0xc000728d20}}, ...)
        /home/runner/work/pulumi-docker/pulumi-docker/provider/hybrid.go:99 +0xdc
    github.com/pulumi/pulumi/sdk/v3/proto/go._ResourceProvider_Invoke_Handler.func1({0x194d228, 0xc0009e1110}, {0x158f420?, 0xc000154040})
        /home/runner/go/pkg/mod/github.com/pulumi/pulumi/sdk/v3@v3.116.1/proto/go/provider_grpc.pb.go:500 +0x75
    github.com/grpc-ecosystem/grpc-opentracing/go/otgrpc.OpenTracingServerInterceptor.func1({0x194d228, 0xc0009e0ea0}, {0x158f420, 0xc000154040}, 0xc0009deb00, 0xc0009d07c8)
        /home/runner/go/pkg/mod/github.com/grpc-ecosystem/grpc-opentracing@v0.0.0-20180507213350-8e809c8a8645/go/otgrpc/server.go:57 +0x3d0
    github.com/pulumi/pulumi/sdk/v3/proto/go._ResourceProvider_Invoke_Handler({0x1651340?, 0xc0006f9bd0}, {0x194d228, 0xc0009e0ea0}, 0xc000257000, 0xc000646240)
        /home/runner/go/pkg/mod/github.com/pulumi/pulumi/sdk/v3@v3.116.1/proto/go/provider_grpc.pb.go:502 +0x135
    google.golang.org/grpc.(*Server).processUnaryRPC(0xc00055d000, {0x194d228, 0xc0009e0e10}, {0x195b440, 0xc00028ad80}, 0xc000b059e0, 0xc000a88c90, 0x24ffcc0, 0x0)
        /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/server.go:1369 +0xe23
    google.golang.org/grpc.(*Server).handleStream(0xc00055d000, {0x195b440, 0xc00028ad80}, 0xc000b059e0)
        /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/server.go:1780 +0x1016
    google.golang.org/grpc.(*Server).serveStreams.func2.1()
        /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/server.go:1019 +0x8b
    created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 84
        /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/server.go:1030 +0x135

    error: Running program '/home/aureq/work/customers/securitas-sps/5336/bin/Debug/net6.0/zendesk.dll' failed with an unhandled exception:
    Grpc.Core.RpcException: Status(StatusCode="Unknown", Detail="invocation of docker:index/getLogs:getLogs returned an error: error reading from server: EOF")
       at async Task<InvokeResponse> Pulumi.GrpcMonitor.InvokeAsync(ResourceInvokeRequest request)
       at async Task<SerializationResult> Pulumi.Deployment.InvokeRawAsync(string token, SerializationResult argsSerializationResult, InvokeOptions options) x 2
       at async Task<T> Pulumi.Deployment.InvokeAsync<T>(string token, InvokeArgs args, InvokeOptions options, bool convertResult)
       at async Task<OutputData<T>> Pulumi.Output<T>+<>c__DisplayClass12_0.<Create>g__GetData|0(?)+GetData(?)
       at async Task<OutputData<U>> Pulumi.Output<T>.ApplyHelperAsync<U>(Task<OutputData<T>> dataTask, Func<T, Output<U>> func)

Affected Resource(s)

Docker.GetLogs

Output of `pulumi about`

CLI          
Version      3.119.0
Go Version   go1.22.3
Go Compiler  gc

Plugins
KIND      NAME    VERSION
resource  docker  4.5.4
language  dotnet  unknown

Host     
OS       debian
Version  12.5
Arch     x86_64

This project is written in dotnet: executable='/usr/bin/dotnet' version='6.0.423'

Current Stack: menfin/zendesk/5336

TYPE                              URN
pulumi:pulumi:Stack               urn:pulumi:5336::zendesk::pulumi:pulumi:Stack::zendesk-5336
pulumi:providers:docker           urn:pulumi:5336::zendesk::pulumi:providers:docker::docker-provider
docker:index/image:Image          urn:pulumi:5336::zendesk::docker:index/image:Image::docker-image
docker:index/container:Container  urn:pulumi:5336::zendesk::docker:index/container:Container::docker-container

Found no pending operations associated with 5336

Backend        
Name           pulumi.com
URL            https://app.pulumi.com/aureq
User           aureq
Organizations  aureq, team-ce, menfin, menfin-team, demo, pulumi
Token type     personal

Dependencies:
NAME           VERSION
Pulumi         3.64.0
Pulumi.Docker  4.5.4

Pulumi locates its logs in /tmp by default

Additional context

As a workaround to avoid the crash, it's possible to execute the container while at the same time retrieving the logs.

    var MyDockerContainer = new Pulumi.Docker.Container("docker-container", new ContainerArgs
    {
        Name = imageName,
        Image = MyDockerImage.Id,
        Attach = true,
        Logs = true,
        MustRun = false,

    }, new CustomResourceOptions
    {
        Provider = MyDockerProvider,
    });

Attach, Logs and MustRun need to be set as shown above and then MyDockerContainer.ContainerLogs should contain the logs generated during the container's execution..

Contributing

Vote on this issue by adding a 👍 reaction. To contribute a fix for this issue, leave a comment (and link to your pull request, if you've opened one already).

VenelinMartinov commented 5 months ago

Thanks for reporting! From a cursory look, this looks like an issue in the upstream provider: https://github.com/kreuzwerker/terraform-provider-docker/blob/master/internal/provider/data_source_docker_logs.go#L118 seems to assume each line of output is at least 8 bytes long, which is wrong in the example you've provided.

I believe this is the same issue as https://github.com/kreuzwerker/terraform-provider-docker/issues/544 upstream, although that issue might have been lost, so it'd be worth raising a new one with the repro here.

blampe commented 5 months ago

Great debugging @VenelinMartinov!

As a workaround to avoid the crash, it's possible to execute the container while at the same time retrieving the logs.

Note that due to https://github.com/kreuzwerker/terraform-provider-docker/issues/545 these logs will probably include some mangled prefixes. Setting discardHeaders to false on the getLogs call should also work around the issue.

While I couldn't get the same error message as our customer

@aureq what error were they seeing?

blampe commented 5 months ago

Removing the p1 label since this is an upstream issue with an existing workaround.

pulumi / pulumi-docker