Javier Ramírez

  • Technology Advocate
  • Docker Captain
  • Docker Certificate Associate
  • Docker Certified Instructor
  • Microsoft Certified Systems Engineer
  • HP Openview Solutions Certified

    • Docker 1.13 Features 3/3

    20 Jan 2017 » docker, swarm

    Following with these series of posts reviewing new docker 1.13 features, there is one thing that we missed when Docker Inc. introduces services on 1.12 version. We used compose to deploy multi-container applications and each block of an application we named “service”. With docker-compose we were able to deploy an application and scale up and down the number of instances of each application block (service). Compose gave us some one-point management tools quite useful. We can use docker-compose ps for reviewing all container instances running to deploy our application and a centralized log  review showing all containers for that service.

    But when we try to use the new “service” concept in docker 1.12, we found that it was really new. Services in 1.12 are related to swarm mode, we can use docker service ps for reviewing instances status and even scale up and down instances, but there isn’t a unique logging for services. We must review service  distribution and enter each node for reading its instance log and troubleshoot what is happening with my deployed service. Remember, on each node…

    In docker 1.13 we have this centralized log for services feature again.

    Using docker service log will show us all logging information of all deployed tasks.

    ubuntu@swarmnode1:~$ docker service logs --help

Usage: docker service logs [OPTIONS] SERVICE

Fetch the logs of a service

Options:
 --details Show extra details provided to logs
 -f, --follow Follow log output
 --help Print usage
 --no-resolve Do not map IDs to Names
 --since string Show logs since timestamp
 --tail string Number of lines to show from the end of the logs (default "all")
 -t, --timestamps Show timestamps

     

    ** ‘details’ option is not available at the time of writing this post.

    We have again a couple of useful options to follow service log and fixing time for troubleshooting proposes.

    Let’s run some examples to show how it works. We will use frjaraur/collectd (https://bitbucket.org/frjaraur/docker-collectd) and we will create a global service using our swarmmode vagrant environment (https://github.com/frjaraur/docker-swarmmode).

    In this example we will create an overlay network called “collectd”

     

    ubuntu@swarmnode1:~$ docker network create -d overlay collectd
thnurheam5gzm3b0p80a6xagk

    And now we deploy the “cagent” global service.

    ubuntu@swarmnode1:~$ docker service create --name cagent --mode global \
> --network collectd \
> --env GRAPHITE_SERVER=graphite \
> --env PLUGINS="docker write_graphite" \
> --label service_name="docker-statistics" \
> --mount type=volume,source=COLLECTD_AGENT,target=/DATA,volume-driver=local \
> --mount type=bind,src=/var/run/docker.sock,dst=/var/run/docker.sock \
> --mount type=bind,src=/etc/timezone,dst=/etc/timezone,readonly \
> --mount type=bind,src=/etc/localtime,dst=/etc/localtime,readonly \
> frjaraur/collectd agent
65qfzcn44q5ya6eyqlw4fhnf6

    We now review service deployment

    ubuntu@swarmnode1:~$ docker service ls
ID NAME MODE REPLICAS IMAGE
65qfzcn44q5y cagent global 4/4 frjaraur/collectd:latest


ubuntu@swarmnode1:~$ docker service ps cagent
ID NAME IMAGE NODE DESIRED STATE CURRENT STATE ERROR PORTS
x7yr8z3mzh54 cagent.luja459j43t8m66cupw6cmmy5 frjaraur/collectd:latest swarmnode4 Running Running 2 minutes ago 
4khq0iqipsve cagent.b063v3wlejutfkkenliuykb2i frjaraur/collectd:latest swarmnode3 Running Running 2 minutes ago 
ip84bd6ptss4 cagent.z8gbkpdrm09dtzdbnmk2tuapj frjaraur/collectd:latest swarmnode2 Running Running 2 minutes ago 
up9b0y56ofan cagent.p73r6eltkovvk9mqlmcvlj6nd frjaraur/collectd:latest swarmnode1 Running Running about a minute ago

    Let’s show the service log for “cagent”

    ubuntu@swarmnode1:~$ docker service logs cagent
cagent.0.up9b0y56ofan@swarmnode1 | plugin_load: plugin "python" successfully loaded.
cagent.0.up9b0y56ofan@swarmnode1 | Docker stats use stream
cagent.0.up9b0y56ofan@swarmnode1 | [2017-02-05 12:36:10] plugin_load: plugin "rrdcached" successfully loaded.
cagent.0.ip84bd6ptss4@swarmnode2 | plugin_load: plugin "python" successfully loaded.
cagent.0.ip84bd6ptss4@swarmnode2 | [2017-02-05 12:35:41] plugin_load: plugin "rrdcached" successfully loaded.
cagent.0.ip84bd6ptss4@swarmnode2 | [2017-02-05 12:35:41] plugin_load: plugin "rrdtool" successfully loaded.
cagent.0.ip84bd6ptss4@swarmnode2 | [2017-02-05 12:35:41] plugin_load: plugin "write_graphite" successfully loaded.
cagent.0.ip84bd6ptss4@swarmnode2 | Docker stats use stream
cagent.0.ip84bd6ptss4@swarmnode2 | [2017-02-05 12:35:41] Collecting stats about Docker containers from unix://var/run/docker.sock (API version 1.25; timeout: 3s).
cagent.0.ip84bd6ptss4@swarmnode2 | [2017-02-05 12:35:41] Initialization complete, entering read-loop.
cagent.0.4khq0iqipsve@swarmnode3 | plugin_load: plugin "python" successfully loaded.
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] plugin_load: plugin "rrdcached" successfully loaded.
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] plugin_load: plugin "rrdtool" successfully loaded.
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] plugin_load: plugin "write_graphite" successfully loaded.
cagent.0.4khq0iqipsve@swarmnode3 | Docker stats use stream
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] Collecting stats about Docker containers from unix://var/run/docker.sock (API version 1.25; timeout: 3s).
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] Initialization complete, entering read-loop.
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:41] Starting stats gathering for 76b2913/cagent.b063v3wlejutfkkenliuykb2i.4khq0iqipsvennoqvqzjeej9u.
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:46] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:51] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:55] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:35:59] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:36:04] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:36:08] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:36:12] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.4khq0iqipsve@swarmnode3 | [2017-02-05 12:36:16] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve
cagent.0.x7yr8z3mzh54@swarmnode4 | plugin_load: plugin "python" successfully loaded.
cagent.0.x7yr8z3mzh54@swarmnode4 | Docker stats use stream
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] plugin_load: plugin "rrdcached" successfully loaded.
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] plugin_load: plugin "rrdtool" successfully loaded.
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] plugin_load: plugin "write_graphite" successfully loaded.
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] Collecting stats about Docker containers from unix://var/run/docker.sock (API version 1.25; timeout: 3s).
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] Initialization complete, entering read-loop.
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:41] Starting stats gathering for 20c3575/cagent.luja459j43t8m66cupw6cmmy5.x7yr8z3mzh54cymvjig1u9k6d.
cagent.0.x7yr8z3mzh54@swarmnode4 | [2017-02-05 12:35:46] write_graphite plugin: getaddrinfo (graphite, 2003, tcp) failed: Name does not resolve

    We can see that there are entries for all of our nodes.

    To avoid these “failed: Name does not resolve” for “graphite”, let’s start “graphite” service too (we are reviewing “docker service logs”, but we can reach graphite on http://0.0.0.0:8080).

    ubuntu@swarmnode1:~$ docker service create --name graphite \
> --network collectd \
> --publish 8080:80 --env RRDDIR=/DATA/collectd/rrd \
> --label service_name="Graphite" \
> --mount type=volume,source=GRAPHITE,target=/var/lib/graphite/storage/whisper,volume-driver=local \
> --mount type=bind,src=/etc/timezone,dst=/etc/timezone,readonly \
> --mount type=bind,src=/etc/localtime,dst=/etc/localtime,readonly \
> frjaraur/graphite start

ij3ebwb0pfaedbu311kzzchwp

    Let’s show again docker service logging information.

    Using –follow will show logging information from all instances as it appears on each container log.

    ubuntu@swarmnode1:~$ docker service logs --follow cagent

cagent.0.up9b0y56ofan@swarmnode1 | [2017-02-05 12:45:09] Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
cagent.0.up9b0y56ofan@swarmnode1 | [2017-02-05 12:45:09] Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
cagent.0.up9b0y56ofan@swarmnode1 | [2017-02-05 12:45:10] Starting stats gathering for 3a5f75c/graphite.1.p0jwhkbml4km6g6di0hf4z15m.
cagent.0.up9b0y56ofan@swarmnode1 | [2017-02-05 12:45:20] write_graphite plugin: Successfully connected to graphite:2003 via tcp.

    Using –timestamp will add time for each entry, this is quite useful if your application’s log does not add this information.

    We have –tail <number_of_lines> (number_of_lines parameter is required and you can use “all” for all entries).

    If you don’t want to resolve container, service and node ids, you can use “–no-resolve”, but I didn’t found it useful as we really want these kind of descriptions for troubleshooting.

    We have reviewed docker system logs and as we have seen its usage is quite simple, but it is a powerful feature missed from 1.12 that thankfully as come again.

    Related Posts