pitkley/dfw

Docker Error: ExpectedError("Object", "null"), module: dfw:503

Closed this issue · 8 comments

Experimenting with dfw and running into an issue running dfw with an empty ruleset (and also with a non-empty ruleset):

# docker version
Client:
 Version:           18.09.7
 API version:       1.39
 Go version:        go1.10.1
 Git commit:        2d0083d
 Built:             Fri Aug 16 14:20:06 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.09.7
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.1
  Git commit:       2d0083d
  Built:            Wed Aug 14 19:41:23 2019
  OS/Arch:          linux/amd64
  Experimental:     false
# docker run --rm \
    --name=dfw
    -v /var/run/docker.sock:/var/run/docker.sock:ro \
    -v /root/dfw:/config \
    --net host \
    --cap-add=NET_ADMIN \
    pitkley/dfw:latest --config-file /config/empty.toml
Sep 23 21:08:00.826 INFO Application started, started_at: 2019-09-23T21:08:00Z, version: 1.0.1-alpha.0, module: dfw:269
Sep 23 21:08:00.828 ERRO Encountered error, error: Docker Error: ExpectedError("Object", "null"), module: dfw:503
# nft -v
nftables v0.8.2 (Joe Btfsplk)
# cat /etc/issue
Ubuntu 18.04.2 LTS \n \l
# curl -f -s --unix-socket /var/run/docker.sock "http:/v1.24/containers/json" | wc -l
1

I'm not sure how to troubleshoot further. Docker is running and I can make requests to the Docker daemon to list running containers (as you can see).

Hm, I'm not sure where or why this is failing. I pushed an update to DFW so that we can maybe retrieve the backtrace and get further insights into where the error actually occurs.

Can you pull the latest tag and rerun the Docker container with the environment variable RUST_BACKTRACE=1 set?

# docker pull pitkley/dfw:latest
# docker run --rm \
    --name=dfw
    -v /var/run/docker.sock:/var/run/docker.sock:ro \
    -v /root/dfw:/config \
    -e RUST_BACKTRACE=1 \
    --net host \
    --cap-add=NET_ADMIN \
    pitkley/dfw:latest --config-file /config/empty.toml

@pitkley
I have the same problem I started the container with RUST_BACKTRACE and empty config file, but no useful info is returned

Jan 28 10:52:57.647 INFO Application started, started_at: 2020-01-28T10:52:57+0000, version: 1.0.2-alpha.0, module: dfw:269
Jan 28 10:52:57.658 ERRO Encountered error, backtrace: stack backtrace:
   0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
, error: Docker Error: ExpectedError("Object", "null"), module: dfw:503
Client: Docker Engine - Community
 Version:           19.03.5
 API version:       1.40
 Go version:        go1.12.12
 Git commit:        633a0ea838
 Built:             Wed Nov 13 07:29:52 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.5
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.12
  Git commit:       633a0ea838
  Built:            Wed Nov 13 07:28:22 2019
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.2.10
  GitCommit:        b34a5c8af56e510852c35414db4c1f4fa6172339
 runc:
  Version:          1.0.0-rc8+dev
  GitCommit:        3e425f80a8c931f88e6d94a8c831b9d5aa481657
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683
Distributor ID: Ubuntu
Description:    Ubuntu 18.04.3 LTS
Release:        18.04
Codename:       bionic

Thanks for reporting @amitbl, I feared as much 😧. I'll really have to check on how to get backtraces, but for the time being: can you execute DFW with --log-level trace set as a command-line argument? It should hopefully give better insights at what stage it fails. 👍

@pitkley Thanks, here is the trace
Edit: I used the updated build now with stack trace

Jan 30 10:04:26.160 DEBG Application starting, started_at: 2020-01-30T10:04:26+0000, version: 1.0.2-alpha.0, module: dfw:162
Jan 30 10:04:26.160 DEBG Initial configuration loaded, config: DFW {
    defaults: None,
    initialization: None,
    container_to_container: None,
    container_to_wider_world: None,
    container_to_host: None,
    wider_world_to_container: None,
    container_dnat: None,
}, module: dfw:172
Jan 30 10:04:26.160 TRCE Pinging docker, module: dfw:180
Jan 30 10:04:26.160 TRCE Creating dummy channel, load_interval: 0, module: dfw:196
Jan 30 10:04:26.160 TRCE Monitoring events: true, monitor_events: true, module: dfw:214
Jan 30 10:04:26.160 TRCE Run once: false, run_once: false, module: dfw:218
Jan 30 10:04:26.160 TRCE Dry run: false, dry_run: false, module: dfw:222
Jan 30 10:04:26.160 TRCE Creating process closure according to load mode, load_mode: once, module: dfw:229
Jan 30 10:04:26.161 TRCE Load mode: Some("once"), module: dfw:263
Jan 30 10:04:26.161 INFO Application started, started_at: 2020-01-30T10:04:26+0000, version: 1.0.2-alpha.0, module: dfw:269
Jan 30 10:04:26.161 DEBG Start first processing, module: dfw:274
Jan 30 10:04:26.161 DEBG Got list of containers, containers: [
    Container {
        Created: 1580378304,
        Command: "docker-entrypoint.sh apache2-foreground",
        Id: "c3b70f83c09a34e68c84401a3a2b8be0b5a227e9811c789276a2b1fae2e244b0",
        Image: "wordpress:latest",
        Labels: {},
        Names: [
            "/lucid_ganguly",
        ],
        Ports: [
            Port {
                IP: None,
                PrivatePort: 80,
                PublicPort: None,
                Type: "tcp",
            },
        ],
        Status: "Up 5 minutes",
        SizeRw: None,
        SizeRootFs: None,
    },
], module: dfw::process:1092
Jan 30 10:04:26.162 TRCE Got map of containers, container_map: {
    "lucid_ganguly": Container {
        Created: 1580378304,
        Command: "docker-entrypoint.sh apache2-foreground",
        Id: "c3b70f83c09a34e68c84401a3a2b8be0b5a227e9811c789276a2b1fae2e244b0",
        Image: "wordpress:latest",
        Labels: {},
        Names: [
            "/lucid_ganguly",
        ],
        Ports: [
            Port {
                IP: None,
                PrivatePort: 80,
                PublicPort: None,
                Type: "tcp",
            },
        ],
        Status: "Up 5 minutes",
        SizeRw: None,
        SizeRootFs: None,
    },
}, module: dfw::process:1097
Jan 30 10:04:26.170 ERRO Encountered error, backtrace: stack backtrace:
   0: failure::backtrace::Backtrace::new
   1: dfw::process::ProcessContext::new
   2: dfw::run::{{closure}}
   3: dfw::run
   4: dfw::main
   5: std::rt::lang_start::{{closure}}
   6: main
, error: Docker Error: ExpectedError("Object", "null"), module: dfw:503

Perfect, thanks @amitbl! Now I'm not sure why, but execution for you fails when DFW is trying to get the networks defined in Docker. Can you provide the output for when you run docker network ls on the host you are running DFW on/for?

@pitkley

NETWORK ID          NAME                  DRIVER              SCOPE
4aqvrfch0l5b        ingress               overlay             swarm

I have found the problem, my docker server was acting as a docker-swarm manager node, creating the above network, leaving the cluster fixed the issue, Thanks for your help.

@amitbl thanks for responding, awesome that you figured the issue out. I'll look into either DFW supporting Swarm, or maybe at least detecting it to give better errors.

@nathangoulding in case you are still using DFW and are still experiencing this issue, maybe being in Swarm is your problem as well? Otherwise, as mentioned above, running a newer version of DFW with backtraces and trace-logging enabled would greatly help.

The issue has been closed due to inactivity of the initial reporter. Feel free to reopen!