log-level behaviour

[dili91]

I'm experiencing some unexpected behaviour when netem delay command is applied on one of my docker container. In order to troubleshoot this I tried to use the --log-level option with debug level. With this option i was just able to see the initial execution plan and not the commands executed while running the test. What am I missing ? I also tried with --tc-image gaiadocker/iproute2 but I can see the same output (except for iproute2 container creation) that is :

➜  ~ docker run -it -v /var/run/docker.sock:/var/run/docker.sock gaiaadm/pumba -l debug netem --tc-image gaiadocker/iproute2 --duration 15s delay --time 1000 mol-mw
DEBU[0000] using names                                   app=pumba function=github.com/alexei-led/pumba/pkg/chaos.GetNamesOrPattern names="[mol-mw]" source="chaos/command.go:47"
DEBU[0000] no interval specified, running only once      app=pumba function=github.com/alexei-led/pumba/pkg/util.GetIntervalValue source="util/util.go:24"
DEBU[0000] no interval specified, running only once      app=pumba function=github.com/alexei-led/pumba/pkg/util.GetIntervalValue source="util/util.go:24"
DEBU[0000] adding network delay to all matching containers  app=pumba function="github.com/alexei-led/pumba/pkg/chaos/netem.(*DelayCommand).Run" source="netem/delay.go:136"
DEBU[0000] listing matching containers                   app=pumba function="github.com/alexei-led/pumba/pkg/chaos/netem.(*DelayCommand).Run" limit=0 names="[mol-mw]" pattern= source="netem/delay.go:141"
DEBU[0000] listing containers                            app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.listContainers source="container/client.go:87"
DEBU[0000] found container                               app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.listContainers id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 name=/mol-mw source="container/client.go:103"
DEBU[0000] found container                               app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.listContainers id=d15c6731002abe228f044e63936d55505d89d3b508c2486b1c0ba3a5d3fde75a name=/mol-db source="container/client.go:103"
DEBU[0000] adding network delay for container            app=pumba container="{{0xc0002ec840 [] 0xc0002db900 0xc000316200} {sha256:b7afdc9225acd8459daf8adccf8f642fca937af241e89b72d5cf21cf030d4a2d [myregistry.com:443/myimage/middleware:1.3.2] [myregistry.com:443/myimage/middleware@sha256:6255786afecea926b869c52caefcf80f1b940b029a8666d647264884d4e30110]   2019-02-15T12:59:24.620736709Z  0xc0002dbcc0 17.12.1-ce  0xc00039a000 amd64 linux  506135620 506135620 {overlay2 map[WorkDir:/var/lib/docker/overlay2/f90eb984a2f92a0fee9af1784e368f7bf65c3f9f5738a7c39185ebdf63a09ef0/work LowerDir:/var/lib/docker/overlay2/6c0cc45955d06a450aa0331054ed337cb9c002b4364a0c7b8bd1e613cf26f31c/diff:/var/lib/docker/overlay2/62fbb5b109017471ef5f59937294dda78ce09984ecf4cce792484b8f48eaa804/diff:/var/lib/docker/overlay2/270f530c1e5f9a668dc036c1eb5e5487c50b6195a0e7057c8ee45ba8afbffdc2/diff:/var/lib/docker/overlay2/42d9edefc2d74322a2ccaa7f21e7f98f86b71498353fbfec6bbfe0f14ba2e04f/diff:/var/lib/docker/overlay2/700aa51ee51f4064644c4699149d55f99942427da179cdd25a34a303504f167d/diff:/var/lib/docker/overlay2/5ff5d42da590426a6f8b9a56d482c03b8661c85c9d0e4b91cc4e804a2db46218/diff:/var/lib/docker/overlay2/1e02b9f20e2ec9ebf4773e3322bbccd3f0c25a6e89f25771aec357e3747659b6/diff:/var/lib/docker/overlay2/98881e74ecc34208dbcc9148813a563adc07f0153ac7b150e0abe993b5950611/diff:/var/lib/docker/overlay2/de2a7762fa158c95ebf2c1e2e24177380f977a0a596c05e0fc917fa34e325d61/diff:/var/lib/docker/overlay2/3fd66cba616524109ed155be5bdb2f6a5a0737ab80271b240743808ca82b13d8/diff:/var/lib/docker/overlay2/b3aadf87c3a53369958efb4e68faa0492ab9104a37587981daabc85cfa57f8bf/diff:/var/lib/docker/overlay2/726aea1e39c6573b512efe6d80141f907bcb6b32e8b4050fbc2b21296aaa20c5/diff:/var/lib/docker/overlay2/7f81b97ef75a0ef4a56650024084b6f637a920bc37a6999c04849a29aecf7f98/diff MergedDir:/var/lib/docker/overlay2/f90eb984a2f92a0fee9af1784e368f7bf65c3f9f5738a7c39185ebdf63a09ef0/merged UpperDir:/var/lib/docker/overlay2/f90eb984a2f92a0fee9af1784e368f7bf65c3f9f5738a7c39185ebdf63a09ef0/diff]} {layers [sha256:4bcdffd70da292293d059d2435c7056711fab2655f8b74f48ad0abe042b63687 sha256:b9914afd042f489b84cfafa104175dd764d2ceeeef523e99b43044d8b224fdd0 sha256:9ae7fb31b323422f25636010c12775b4b7d6a98c906776e38bf80af92edb9e6f sha256:9494291c711c91aed01cb58cdab8691dc6831e7bbd4413ece228d2a5e619a536 sha256:e4aca0ca8d27e116779294b7f15039d648451cdbefe045bbcfd2266808e7e6a0 sha256:761641491dc5decbd3b8f5344c60a08bcf43817a19064ed0071efc5dee7ed36d sha256:6b5cd193aae07235cbb29af87607d483db09916795ab4b6da47e64f0d9b2da1f sha256:3f55fa4690edaa1adfd40e72d76bdb8de146ca6b2103b5fdf678a927b6ac04d1 sha256:c75fb5614c62809368b3622930ba4a4dbf58f384a15737f4879d738f586264d6 sha256:dfa7a0fe6f262b15449add3397dae712a6f86f3c18730ad4b48f21bf5cc5a35c sha256:f7ba16ac272cc6344ce1e173b059de9315f7311a4ee7341a3fe4a2c6b30e1603 sha256:76fcfff0056e0c35c75950b165f31c968cab6cf2594d7928c2d4ea983dfdcf79 sha256:cf0b94c88a97fbf4c8d9ea9e589225c88cb75e49688eca75277702d24cadf2a3 sha256:d86aafe5f6b04b9fe97621d0817806c7e2b2002e25dac383d00d627a9ed65ef3] }}}" function="github.com/alexei-led/pumba/pkg/chaos/netem.(*DelayCommand).Run" source="netem/delay.go:179"
DEBU[0000] running netem command                         app=pumba duration=15s function=github.com/alexei-led/pumba/pkg/chaos/netem.runNetem id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 iface=eth0 ips="[]" name=/mol-mw netem="[delay 1000ms 10ms 20.00]" pull=true source="netem/netem.go:23" tc-image=gaiadocker/iproute2
INFO[0000] Running netem command '[delay 1000ms 10ms 20.00]' on container 9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 for 15s  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.NetemContainer source="container/client.go:233"
INFO[0000] start netem for container                     app=pumba dryrun=false function=github.com/alexei-led/pumba/pkg/container.dockerClient.startNetemContainer id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 iface=eth0 name=/mol-mw netem="delay 1000ms 10ms 20.00" pull=true source="container/client.go:291" tcimage=gaiadocker/iproute2
DEBU[0000] adding netem qdisc                            app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.startNetemContainer netem="qdisc add dev eth0 root netem delay 1000ms 10ms 20.00" source="container/client.go:299"
DEBU[0000] executing tc command                          app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:469" tc args="[qdisc add dev eth0 root netem delay 1000ms 10ms 20.00]" tcimage=gaiadocker/iproute2
DEBU[0000] network mode                                  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand network="container:9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13" source="container/client.go:491"
DEBU[0000] pulling tc image                              app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand image=gaiadocker/iproute2 source="container/client.go:494"
DEBU[0001] &{Pulling from gaiadocker/iproute2   {0 0}}   app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0001] &{Digest: sha256:d0cd5819fbeaf2e7501dcb223bb5bad4fda7c1e76ff9877baba6e559c70b6d1e   {0 0}}  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0001] &{Status: Image is up to date for gaiadocker/iproute2:latest   {0 0}}  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0001] creating tc container                         app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand image=gaiadocker/iproute2 source="container/client.go:513"
DEBU[0001] tc container created, starting it             app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand id=cd849ebc858820b9c7f0f1a18c56fc4510c3e9cf005a04027e4c2a9698c7bfbf source="container/client.go:519"


DEBU[0017] stopping netem command on timout              app=pumba function=github.com/alexei-led/pumba/pkg/chaos/netem.runNetem id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 iface=eth0 ips="[]" name=/mol-mw source="netem/netem.go:53" tc-image=gaiadocker/iproute2
INFO[0017] stopping netem on container                   IPs="[]" app=pumba dryrun=false function=github.com/alexei-led/pumba/pkg/container.dockerClient.StopNetemContainer id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 iface=eth0 name=/mol-mw pull=true source="container/client.go:254" tc-image=gaiadocker/iproute2
INFO[0017] stop netem for container                      IPs="[]" app=pumba dryrun=false function=github.com/alexei-led/pumba/pkg/container.dockerClient.stopNetemContainer id=9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13 iface=eth0 name=/mol-mw pull=true source="container/client.go:314" tcimage=gaiadocker/iproute2
DEBU[0017] deleting netem qdisc                          app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.stopNetemContainer netem="qdisc del dev eth0 root netem" source="container/client.go:357"
DEBU[0017] executing tc command                          app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:469" tc args="[qdisc del dev eth0 root netem]" tcimage=gaiadocker/iproute2
DEBU[0017] network mode                                  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand network="container:9d67a588ec0d7b83393f2bdb9afa056903254a3fe3e81351bfcf6b59f7140a13" source="container/client.go:491"
DEBU[0017] pulling tc image                              app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand image=gaiadocker/iproute2 source="container/client.go:494"
DEBU[0018] &{Pulling from gaiadocker/iproute2   {0 0}}   app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0018] &{Digest: sha256:d0cd5819fbeaf2e7501dcb223bb5bad4fda7c1e76ff9877baba6e559c70b6d1e   {0 0}}  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0018] &{Status: Image is up to date for gaiadocker/iproute2:latest   {0 0}}  app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand source="container/client.go:510"
DEBU[0018] creating tc container                         app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand image=gaiadocker/iproute2 source="container/client.go:513"
DEBU[0018] tc container created, starting it             app=pumba function=github.com/alexei-led/pumba/pkg/container.dockerClient.tcContainerCommand id=f79c24e4a7b69234781ada56000b9f73640188c26f4a00d28224f0eeeb39860c source="container/client.go:519"

[alexei-led]

@dili91 ok, it's still not clear what is the problem. Log is very detailed and shows every tc command it runs on Docker container network. Take a look at arguments, maybe you will find what are you looking for.

[dili91]

Hello, basically I was expecting to see traffic logs with log level set to debug but I might have misunderstood. I'd like to check those because latency applied to the targeted container is not inline with the netem delay I set. I guess due to some unexpected internal loop, which I wanted to troubleshoot. Is there a way I can do it ? Thank you

[alexei-led]

@dili91 take a look at code and if you see any unexpected delay suggest a PR. You can also try to run tc command and check how does it behave (that is what pumba does)