Docker Community Forums

Share and learn in the Docker community.

'docker service logs' seems to hang after printing large output in a short time

(Gypark) #1


I’m not good at English, plz understand it.
And if this topic is a duplicated one. I’m sorry about it.

I ran a service and found… the service log output was strange, like it becomes hang or stalled after it prints large number of lines rapidly. It’s like… a sort of ‘log queue full’

Here is my docker version:

 Version:       18.03.0-ce
 API version:   1.37
 Go version:    go1.9.4
 Git commit:    0520e24
 Built: Wed Mar 21 23:09:15 2018
 OS/Arch:       linux/amd64
 Experimental:  false
 Orchestrator:  swarm

  Version:      18.03.0-ce
  API version:  1.37 (minimum version 1.12)
  Go version:   go1.9.4
  Git commit:   0520e24
  Built:        Wed Mar 21 23:13:03 2018
  OS/Arch:      linux/amd64
  Experimental: false

At first, I saw this problem from the log of PostgreSQL service. I wanted to reproduce it with a simple example so I made a short Perl script:

$ cat
# just prints from 1 to 10000000.
for ( 1 .. 10_000_000 ) {
   print "> $_\n";

If I run this script using Perl image in foreground, it works well:

$ docker run --name test -it -v ${PWD}:/app perl:5.26 perl /app/
> 1
> 2
> 10000000

If I run it in background and try to docker logs --follow it, it works well again:

$ docker run -d --name test -it -v ${PWD}:/app perl:5.26 perl /app/ && docker logs -f test
<container ID>
> 1
> 2
> 10000000

But, when I run it via Docker service and try to see its log, only a part of the logs are printed and the rest of logs are printed very slowly. It took 10 seconds per a line.

$ docker service create --name test --mount type=bind,src=${PWD},dst=/app --constraint 'node.hostname == YRECOMT1' --restart-condition none perl:5.26 perl /app/
overall progress: 1 out of 1 tasks
1/1: running   [==================================================>]
verify: Waiting 2 seconds to verify that tasks are stable...

$ docker service logs -f test
test.1.mevziwr6ljic@YRECOMT1    | > 1
test.1.mevziwr6ljic@YRECOMT1    | > 2
test.1.mevziwr6ljic@YRECOMT1    | > 1159690  # stopped here
test.1.mevziwr6ljic@YRECOMT1    | > 1159691  # printed after about 10 seconds
test.1.mevziwr6ljic@YRECOMT1    | > 1159692  # after 10 seconds
test.1.mevziwr6ljic@YRECOMT1    | > 1159693  # after 10 seconds

Of course the service itself has been shutdown state long ago(it just do a loop and exit). But this also happens even when I use docker service logs without --follow.

$ docker service logs test
test.1.mevziwr6ljic@YRECOMT1    | > 1159690  # stopped here
test.1.mevziwr6ljic@YRECOMT1    | > 1159691  # printed after about 10 seconds

But, docker logs on the “task” container instead of “service” works well:

$ docker logs test.1.rnzkscj4pzy365dgxt3n5sngx
> 1
> 10000000

docker service logs --tail 10 shows that a successful result of the task:

$ docker service logs --tail 10 test
test.1.mevziwr6ljic@YRECOMT1    | > 9999991
test.1.mevziwr6ljic@YRECOMT1    | > 9999992
test.1.rnzkscj4pzy3@YRECOMT1    | > 9999993
test.1.mevziwr6ljic@YRECOMT1    | > 10000000

So I guess there might be a problem related to a buffer capacity? size? limit? whatever.

As I’ve said above, I found this problem when I was seeing the log of a PostgreSQL service. My collegue was trying to insert 300,000 rows in a DB and the log hang after showing about 56000’th rows, then it prints a log for inserting a row every 90 seconds.

If this is just a problem of log, it would be tolerable. But he said that it seemed that the PostgreSQL service itself hang after such large-scale inserting. I’m investigating it for now.

Any advice would be appreciated.
Thank you.

This is my docker info output, if it would be helpful:

Containers: 13                                                                                                                                                                                                         
 Running: 10
 Paused: 0
 Stopped: 3
Images: 316
Server Version: 18.03.0-ce
Storage Driver: devicemapper
 Pool Name: docker-8:4-12885517380-pool
 Pool Blocksize: 65.54kB
 Base Device Size: 10.74GB
 Backing Filesystem: xfs
 Udev Sync Supported: true
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data loop file: /var/lib/docker/devicemapper/devicemapper/data
 Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata
 Data Space Used: 11.69GB
 Data Space Total: 107.4GB
 Data Space Available: 95.68GB
 Metadata Space Used: 20.97MB
 Metadata Space Total: 2.147GB
 Metadata Space Available: 2.127GB
 Thin Pool Minimum Free Space: 10.74GB
 Deferred Removal Enabled: true
 Deferred Deletion Enabled: true
 Deferred Deleted Device Count: 0
 Library Version: 1.02.140-RHEL7 (2017-05-03)
Logging Driver: json-file
Cgroup Driver: cgroupfs
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: active
 NodeID: w65vfus5doyotlau9q8c1793u
 Is Manager: true
 ClusterID: lgc2xrz6qhog5v73cu0k0w47d
 Managers: 1
 Nodes: 3
  Task History Retention Limit: 5
  Snapshot Interval: 10000
  Number of Old Snapshots to Retain: 0
  Heartbeat Tick: 1
  Election Tick: 3
  Heartbeat Period: 5 seconds
 CA Configuration:
  Expiry Duration: 3 months
  Force Rotate: 0
 Autolock Managers: false
 Root Rotation In Progress: false
 Node Address:
 Manager Addresses:
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: cfd04396dc68220d1cecbe686a6cc3aa5ce3667c
runc version: 4fc53a81fb7c994640722ac585fa9ca548971871
init version: 949e6fa
Security Options:
  Profile: default
Kernel Version: 3.10.0-693.17.1.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 20
Total Memory: 62.64GiB
Name: *******
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Username: gypark
Experimental: false
Insecure Registries:
Live Restore Enabled: false