search

oracle / railcar

RailCar: Rust implementation of the Open Containers Initiative oci-runtime
Other
1.12k stars 101 forks source link

Unable to use rc as runtime for docker : run command hangs indefinitely. #32

Closed rkgade closed 6 years ago

rkgade commented 6 years ago

Steps performed :

  1. compile and build railcar. rc is an alias.

    $ rc -V
Railcar 1.0.4

  2. added railcar as runtime for docker

    $ cat work/src/scripts/do_run_dockerd.sh 
sudo /usr/bin/dockerd --debug --log-level debug --data-root /home/rgade/docker-data-root --exec-root /home/rgade/docker-exec-root  --pidfile /home/rgade/docker.pid  --experimental --add-runtime "rc=/home/rgade/railcar/railcar" -H unix:///home/rgade/docker.sock -H tcp://0.0.0.0:2375

  3. Started docker daemon log is listed below.

  4. tried to run two containers, one as daemon , one with command

    • This one hung indedinitely. $ docker run -dt --rm --runtime rc nginx d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7

docker ps -a output

 $ docker ps -a
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES
ef6b37f13ff4        busybox             "top"                    25 minutes ago      Created                                 boring_wiles
d3a1605e166d        nginx               "nginx -g 'daemon of…"   27 minutes ago      Created                                 nostalgic_hugle

docker version

$ docker version Client: Version: 18.01.0-ce API version: 1.35 Go version: go1.9.2 Git commit: 03596f51b1 Built: Sun Jan 14 23:10:39 2018 OS/Arch: linux/amd64 Experimental: false Orchestrator: swarm

Server: Engine: Version: 18.01.0-ce API version: 1.35 (minimum version 1.12) Go version: go1.9.2 Git commit: 03596f51b1 Built: Sun Jan 14 23:11:14 2018 OS/Arch: linux/amd64 Experimental: true

what I couldn't find.

  1. Log of railcar when run as docker backed. One of my query is whether this is implemented or not ( logging of railcar when used as backed for docker ). did try this though : 
    sudo /usr/bin/dockerd --debug --log-level debug --data-root /home/rgade/docker-data-root --exec-root /home/rgade/docker-exec-root  --pidfile /home/rgade/docker.pid  --experimental --add-runtime "rc=/home/rgade/railcar/railcar -v --log /home/rgade/rc.log " -H unix:///home/rgade/docker.sock -H tcp://0.0.0.0:2375

    Didn't work, of course. Not really sure if that is the way!

Couldn't get logs for railcar run -v --log <filename> <subcommand> as well. Couldn't see accessing logfile in code. Saw your PR #30 for 17.12 changes but does it also write to log file after touch ing it?

Log when run command was executed for nginx

time="2018-01-23T12:56:15.967017788+05:30" level=debug msg="Calling POST /v1.35/containers/create" time="2018-01-23T12:56:15.967337209+05:30" level=debug msg="form data: {\"AttachStderr\":false,\"AttachStdin\":false,\"AttachStdout\":false,\"Cmd\":null,\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":[],\"HostConfig\":{\"AutoRemove\":true,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"Devices\":[],\"DiskQuota\":0,\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"Runtime\":\"rc\",\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"nginx\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":true,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}" time="2018-01-23T12:56:16.115736991+05:30" level=debug msg="container mounted via layerStore: &{/home/rgade/docker-data-root/overlay2/e773fd14e1e23e71b59c088bc506bd3e8690142f9f9c609083c482c42f82384a/merged 0x55c998dc10e0 0x55c998dc10e0}" time="2018-01-23T12:56:16.217428012+05:30" level=debug msg="Calling POST /v1.35/containers/d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7/wait?condition=removed" time="2018-01-23T12:56:16.218423541+05:30" level=debug msg="Calling POST /v1.35/containers/d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7/start" time="2018-01-23T12:56:16.220286574+05:30" level=debug msg="container mounted via layerStore: &{/home/rgade/docker-data-root/overlay2/e773fd14e1e23e71b59c088bc506bd3e8690142f9f9c609083c482c42f82384a/merged 0x55c998dc10e0 0x55c998dc10e0}" time="2018-01-23T12:56:16.221067450+05:30" level=debug msg="Assigning addresses for endpoint nostalgic_hugle's interface on network bridge" time="2018-01-23T12:56:16.221118112+05:30" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, , map[])" time="2018-01-23T12:56:16.305129365+05:30" level=debug msg="Assigning addresses for endpoint nostalgic_hugle's interface on network bridge" time="2018-01-23T12:56:16.463674041+05:30" level=debug msg="Programming external connectivity on endpoint nostalgic_hugle (b99f4cb5aea4cc3dd5f32a5e43405d3b33ac840068b9c265e6b590696c799be7)" time="2018-01-23T12:56:16.505383138+05:30" level=debug msg="EnableService d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7 START" time="2018-01-23T12:56:16.505444755+05:30" level=debug msg="EnableService d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7 DONE" time="2018-01-23T12:56:16.534986694+05:30" level=debug msg="bundle dir created" bundle=/home/rgade/docker-exec-root/containerd/d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7 module=libcontainerd namespace=moby root=/home/rgade/docker-data-root/overlay2/e773fd14e1e23e71b59c088bc506bd3e8690142f9f9c609083c482c42f82384a/merged time="2018-01-23T12:56:16+05:30" level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/create" type=containerd.events.ContainerCreate time="2018-01-23T12:56:16+05:30" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/d3a1605e166db1bc66307b44ced44b1f25b98621b08b4ead59888314bdcd57e7/shim.sock" debug=true module="containerd/tasks" pid=3683 time="2018-01-23T12:56:16+05:30" level=debug msg="registering ttrpc server" time="2018-01-23T12:56:16+05:30" level=debug msg="serving api on unix socket" socket="[inherited from parent]"** time="2018-01-23T12:56:20.037948729+05:30" level=debug msg="Calling GET /_ping" time="2018-01-23T12:56:20.038363211+05:30" level=debug msg="Calling GET /v1.35/containers/json" time="2018-01-23T12:56:21.857977024+05:30" level=debug msg="Calling GET /_ping" time="2018-01-23T12:56:21.858486285+05:30" level=debug msg="Calling GET /v1.35/containers/json?all=1" time="2018-01-23T12:58:14.998614842+05:30" level=debug msg="Calling GET /_ping"

Log when busybox top command was executed

time="2018-01-23T12:58:15.000655981+05:30" level=debug msg="Calling POST /v1.35/containers/create" time="2018-01-23T12:58:15.001056327+05:30" level=debug msg="form data: {\"AttachStderr\":false,\"AttachStdin\":false,\"AttachStdout\":false,\"Cmd\":[\"top\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":[],\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"Devices\":[],\"DiskQuota\":0,\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"Runtime\":\"rc\",\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}" time="2018-01-23T12:58:15.160084075+05:30" level=debug msg="container mounted via layerStore: &{/home/rgade/docker-data-root/overlay2/b19f835f06529a1e9fd54e19d1629c61383961b8315069220049943ad468f0c9/merged 0x55c998dc10e0 0x55c998dc10e0}" time="2018-01-23T12:58:15.289854905+05:30" level=debug msg="Calling POST /v1.35/containers/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c/wait?condition=next-exit" time="2018-01-23T12:58:15.290809147+05:30" level=debug msg="Calling POST /v1.35/containers/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c/start" time="2018-01-23T12:58:15.292197939+05:30" level=debug msg="container mounted via layerStore: &{/home/rgade/docker-data-root/overlay2/b19f835f06529a1e9fd54e19d1629c61383961b8315069220049943ad468f0c9/merged 0x55c998dc10e0 0x55c998dc10e0}" time="2018-01-23T12:58:15.292905090+05:30" level=debug msg="Assigning addresses for endpoint boring_wiles's interface on network bridge" time="2018-01-23T12:58:15.292956264+05:30" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, , map[])" time="2018-01-23T12:58:15.399990240+05:30" level=debug msg="Assigning addresses for endpoint boring_wiles's interface on network bridge" time="2018-01-23T12:58:15.608321003+05:30" level=debug msg="Programming external connectivity on endpoint boring_wiles (c6f1bee88855a83e11c77860291c5b9e1e4ea7e39dfd515c78da3c1bc6b05201)" time="2018-01-23T12:58:15.649952419+05:30" level=debug msg="EnableService ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c START" time="2018-01-23T12:58:15.650012862+05:30" level=debug msg="EnableService ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c DONE" time="2018-01-23T12:58:15.690161560+05:30" level=debug msg="bundle dir created" bundle=/home/rgade/docker-exec-root/containerd/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c module=libcontainerd namespace=moby root=/home/rgade/docker-data-root/overlay2/b19f835f06529a1e9fd54e19d1629c61383961b8315069220049943ad468f0c9/merged time="2018-01-23T12:58:15+05:30" level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/create" type=containerd.events.ContainerCreate time="2018-01-23T12:58:15+05:30" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c/shim.sock" debug=true module="containerd/tasks" pid=3759 time="2018-01-23T12:58:15+05:30" level=debug msg="registering ttrpc server" time="2018-01-23T12:58:15+05:30" level=debug msg="serving api on unix socket" socket="[inherited from parent]" time="2018-01-23T12:58:16+05:30" level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/create" type=containerd.events.TaskCreate time="2018-01-23T12:58:16.023661011+05:30" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create time="2018-01-23T12:58:16+05:30" level=error msg="OCI runtime state failed: unable to retrieve OCI runtime error (open /home/rgade/docker-exec-root/containerd/daemon/io.containerd.runtime.v1.linux/moby/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c/log.json: no such file or directory): invalid character 'W' looking for beginning of value: unknown" module="containerd/tasks" time="2018-01-23T12:58:16+05:30" level=fatal msg="containerd-shim: ttrpc server failure" error="ttrpc: server close" time="2018-01-23T12:58:16+05:30" level=debug msg="received signal" module=containerd signal=child exited time="2018-01-23T12:58:16+05:30" level=info msg="shim reaped" id=ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c module="containerd/tasks" time="2018-01-23T12:58:16+05:30" level=warning msg="cleaning up after killed shim" id=ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c module="containerd/tasks" namespace=moby time="2018-01-23T12:58:16+05:30" level=debug msg="received signal" module=containerd signal=child exited time="2018-01-23T12:58:16+05:30" level=debug msg="received signal" module=containerd signal=child exited time="2018-01-23T12:58:16+05:30" level=debug msg="event published" ns=moby topic="/tasks/exit" type=containerd.events.TaskExit time="2018-01-23T12:58:16.228476413+05:30" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit time="2018-01-23T12:58:16+05:30" level=debug msg="event published" ns=moby topic="/tasks/delete" type=containerd.events.TaskDelete time="2018-01-23T12:58:16.228540920+05:30" level=warning msg="Ignoring Exit Event, no such exec command found" container=ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c exec-id=ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c exec-pid=3769 time="2018-01-23T12:58:16.228713994+05:30" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete time="2018-01-23T12:58:16.228734124+05:30" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete" time="2018-01-23T12:58:16+05:30" level=debug msg="received signal" module=containerd signal=terminated time="2018-01-23T12:58:16.232833575+05:30" level=error msg="failed to get event" error="rpc error: code = Internal desc = transport is closing" module=libcontainerd namespace=moby time="2018-01-23T12:58:16.232961375+05:30" level=error msg="failed to delete task after fail start" container=ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c error="transport is closing: unknown" module=libcontainerd namespace=moby time="2018-01-23T12:58:16.237339462+05:30" level=error msg="stream copy error: reading from a closed fifo" time="2018-01-23T12:58:16.232832590+05:30" level=error msg="failed to get event" error="rpc error: code = Internal desc = transport is closing" module=libcontainerd namespace=plugins.moby time="2018-01-23T12:58:19.365667766+05:30" level=debug msg="daemon is not responding" binary=docker-containerd error="rpc error: code = DeadlineExceeded desc = context deadline exceeded" module=libcontainerd time="2018-01-23T12:58:19.367399412+05:30" level=info msg="libcontainerd: started new docker-containerd process" pid=3782 time="2018-01-23T12:58:19+05:30" level=info msg="starting containerd" module=containerd revision=89623f28b87a6004d4b785663257362d1658a729 version=v1.0.0 time="2018-01-23T12:58:19+05:30" level=info msg="setting subreaper..." module=containerd time="2018-01-23T12:58:19+05:30" level=info msg="changing OOM score to -500" module=containerd time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.content.v1.content"..." module=containerd type=io.containerd.content.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." module=containerd type=io.containerd.snapshotter.v1 time="2018-01-23T12:58:19+05:30" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /home/rgade/docker-data-root/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" module=containerd time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." module=containerd type=io.containerd.snapshotter.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." module=containerd type=io.containerd.metadata.v1 time="2018-01-23T12:58:19+05:30" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /home/rgade/docker-data-root/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" module="containerd/io.containerd.metadata.v1.bolt" time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." module=containerd type=io.containerd.differ.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." module=containerd type=io.containerd.gc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." module=containerd type=io.containerd.monitor.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." module=containerd type=io.containerd.runtime.v1 time="2018-01-23T12:58:19+05:30" level=debug msg="loading tasks in namespace" module="containerd/io.containerd.runtime.v1.linux" namespace=moby time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." module=containerd type=io.containerd.grpc.v1 time="2018-01-23T12:58:19+05:30" level=info msg=serving... address="/home/rgade/docker-exec-root/containerd/docker-containerd-debug.sock" module="containerd/debug" time="2018-01-23T12:58:19+05:30" level=info msg=serving... address="/home/rgade/docker-exec-root/containerd/docker-containerd.sock" module="containerd/grpc" time="2018-01-23T12:58:19+05:30" level=info msg="containerd successfully booted in 0.013588s" module=containerd time="2018-01-23T12:58:19+05:30" level=debug msg="received signal" module=containerd signal=broken pipe time="2018-01-23T12:58:19+05:30" level=debug msg="event published" module="containerd/containers" ns=moby topic="/containers/delete" type=containerd.events.ContainerDelete time="2018-01-23T12:58:19+05:30" level=debug msg="garbage collected" d=68.424828ms module="containerd/io.containerd.gc.v1.scheduler" time="2018-01-23T12:58:19.583679923+05:30" level=debug msg="Revoking external connectivity on endpoint boring_wiles (c6f1bee88855a83e11c77860291c5b9e1e4ea7e39dfd515c78da3c1bc6b05201)" time="2018-01-23T12:58:19.587519776+05:30" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0" time="2018-01-23T12:58:19.808334991+05:30" level=debug msg="Releasing addresses for endpoint boring_wiles's interface on network bridge" time="2018-01-23T12:58:19.808402932+05:30" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.3)" time="2018-01-23T12:58:19.931098021+05:30" level=error msg="ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c cleanup: failed to delete container from containerd: no such container" time="2018-01-23T12:58:19.931211392+05:30" level=error msg="Handler for POST /v1.35/containers/ef6b37f13ff4b30d88484f43606d4f3f910a0a8701ef2c7a25ad98dcb460c95c/start returned error: ttrpc: client shutting down: EOF: unknown"

time="2018-01-23T12:58:29.479560177+05:30" level=debug msg="Calling GET /_ping" time="2018-01-23T12:58:29.480027996+05:30" level=debug msg="Calling GET /v1.35/containers/json" time="2018-01-23T12:58:31.099764158+05:30" level=debug msg="Calling GET /_ping" time="2018-01-23T12:58:31.100198302+05:30" level=debug msg="Calling GET /v1.35/containers/json?all=1" time="2018-01-23T12:58:40.512113963+05:30" level=debug msg="Calling GET /_ping" time="2018-01-23T12:58:40.512568079+05:30" level=debug msg="Calling GET /v1.35/containers/boring_wiles/json"

rkgade commented 6 years ago

Update

Executed successfully with 'fixes' branch code. However, was not able to log output to file. Hence, raised a PR #33 . Tested it as well. Please have a look.

vishvananda commented 6 years ago

thanks for the detailed description. I'm glad to know it works with the fixes branch. I've now merged it. The logging functionality is a known issue. I think if you modified your patch to support --log-format as well and log in json then I can merge it. You will have to sign the oracle CLA of course as mentioned in the contributing guidelines.

rkgade commented 6 years ago

Thank you for the update, Vish Abrams. Shall update for json format as well. And yes, some fixes branch issue was there. Now that you merged, will take up master.

Regards, Raj Kiran Gade

On Wed, 24 Jan 2018 at 05:26, Vish (Ishaya) Abrams notifications@github.com wrote:

thanks for the detailed description. I'm glad to know it works with the fixes branch. I've now merged it. The logging functionality is a known issue. I think if you modified your patch to support --log-format as well and log in json then I can merge it. You will have to sign the oracle CLA of course as mentioned in the contributing guidelines.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/oracle/railcar/issues/32#issuecomment-359972901, or mute the thread https://github.com/notifications/unsubscribe-auth/AJ30NRqX_oBZYz_CKrG8ujxr-aDIoivRks5tNnGSgaJpZM4RpO_F .

-- Regards, Raj Kiran Gade

rkgade commented 6 years ago

I just have one more query. How does Docker set it? And if it does, to what values would that set it to? Is there a way we can find out. I am asking this because, I was not able to pass -v and —log options to RC like the following : dockerd —experimental .... “rc=railcar -v --log

But at the end of the day, all we need are the logs written by railcar, working as a backend for docker.

Is there anything I am missing here?

Thanks for your email and merge of fixes branch. Will work on JSON.

Regards, Raj Kiran Gade

On Wed, 24 Jan 2018 at 06:40, Raj Kiran Gade rajkiran.gade@gmail.com wrote:

Thank you for the update, Vish Abrams. Shall update for json format as well. And yes, some fixes branch issue was there. Now that you merged, will take up master.

Regards, Raj Kiran Gade

On Wed, 24 Jan 2018 at 05:26, Vish (Ishaya) Abrams < notifications@github.com> wrote:

thanks for the detailed description. I'm glad to know it works with the fixes branch. I've now merged it. The logging functionality is a known issue. I think if you modified your patch to support --log-format as well and log in json then I can merge it. You will have to sign the oracle CLA of course as mentioned in the contributing guidelines.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/oracle/railcar/issues/32#issuecomment-359972901, or mute the thread https://github.com/notifications/unsubscribe-auth/AJ30NRqX_oBZYz_CKrG8ujxr-aDIoivRks5tNnGSgaJpZM4RpO_F .

-- Regards, Raj Kiran Gade

-- Regards, Raj Kiran Gade

vishvananda commented 6 years ago

every command docker runs against the backend has values similar to the following: "--log", "/run/docker/containerd/daemon/io.containerd.runtime.v1.linux/moby/a63ae639789cfb26977d7ad94a1769dd115e5ddc9ba23d4f568b13f7b52c577b/log.json", "--log-format", "json"

Where the long hex string is the container id. I'm not sure exactly what the json format is supposed to look like but i'm sure it could be found by looking at runc.

rkgade commented 6 years ago

Yes. I could see logs like that. But was wondering what would the key and values be in JSON.

$ docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 5fb8f23a0b0f nginx "nginx -g 'daemon of…" 47 seconds ago Up 45 seconds 0.0.0.0:80->80/tcp keen_hugle

$ docker logs keen_hugle 172.17.0.1 - - [24/Jan/2018:05:57:12 +0000] "GET / HTTP/1.1" 200 612 "-" "curl/7.57.0" "-" 172.17.0.1 - - [24/Jan/2018:05:57:41 +0000] "GET / HTTP/1.1" 200 612 "-" "curl/7.57.0" "-"

[hogwarts 5fb8f23a0b0f941917d7b9a1386f38b200739b3d6e8e347441d07ae7d2f5e3c8]# cat 5fb8f23a0b0f941917d7b9a1386f38b200739b3d6e8e347441d07ae7d2f5e3c8-json.log

{"log":"172.17.0.1 - - [24/Jan/2018:05:57:12 +0000] \"GET / HTTP/1.1\" 200 612 \"-\" \"curl/7.57.0\" \"-\"\r\n","stream":"stdout","time":"2018-01-24T05:57:12.583118365Z"}

{"log":"172.17.0.1 - - [24/Jan/2018:05:57:41 +0000] \"GET / HTTP/1.1\" 200 612 \"-\" \"curl/7.57.0\" \"-\"\r\n","stream":"stdout","time":"2018-01-24T05:57:41.083619427Z"}

Here, key is "log" and everything is just value. Would such implementation be fine? I guess it's just json::stringify(, < record args> ) and then writing the output to file.

Please share your thoughts.

vishvananda commented 6 years ago

according to https://github.com/sirupsen/logrus/blob/master/json_formatter.go the format is as follows: { "msg": "", "level": "DEBUG", // or INFO etc. "time": "XXX" // time in RFC3339 format }

rkgade commented 6 years ago

hmm. ok. Thank you for the link. Will try and implement the same.

rkgade commented 6 years ago

This would need a change in debug!() as well. It should include timestamp. We can't create a timestamp while writing to file, right as there might be a delta.

So, instead of DEBUG = ensuring railcar state dir /home/rgade/railcar_state/ we should have "log" : [< timestamp >] [DEBUG] [ensuring railcar state dir /home/rgade/railcar_state/]

vishvananda commented 6 years ago

the line should look like: {"msg":"ensuring railcar state dir /home/rgade/railcar_state/", "level":"DEBUG","time":"<timestamp>"} it is fine to set the timestamp when writing to file. The delta would be miniscule

rkgade commented 6 years ago

Thank you for the info. There are a few more things I am looking at when thinking about logging mecahnism. Will come up with PR that works both Docker ways and standalone way. I am closing this issue and shall delete the PR #33 as it contains some old codebase.