Trying to understand what’s happening inside your code running in multiple docker-compose containers by reading logs could be a terrible idea if log lines are outputted in a random manner. Which is true at least for docker-compose version 1.8.0, build 94f7016. This could be simply checked by running the following command several times.
docker-compose logs|head
Here are my examples:
RUN 1
#docker-compose -f docker-compose-all.yml logs -t|head
Attaching to oauth_web_1, oauth_core_1, oauth_core-ok_1, oauth_core-fb_1, oauth_oauth_1, oauth_fill-sqls-web_1, oauth_fill-sqls-oauth_1, oauth_web-redis_1, oauth_core-redis_1, oauth_core-mysql_1, oauth_oauth-mysql_1, oauth_web-mysql_1
core_1 | 2016-10-07T06:22:10.603699134Z [nodemon] 1.10.2
core_1 | 2016-10-07T06:22:10.604808539Z [nodemon] to restart at any time, enter `rs`
core_1 | 2016-10-07T06:22:10.605207552Z [nodemon] watching: /usr/src/app/**/*
core_1 | 2016-10-07T06:22:10.605788544Z [nodemon] starting `node --debug=3010 --max_old_space_size=4096 serverApi.js`
core_1 | 2016-10-07T06:22:10.935801570Z Debugger listening on [::]:3010
core_1 | 2016-10-07T06:23:44.499687810Z :4443
core-ok_1 | 2016-10-07T06:22:03.932151348Z npm info it worked if it ends with ok
core_1 | 2016-10-07T06:47:00.701059229Z
core_1 | 2016-10-07T06:47:00.701097632Z --- mainParams [ { configuration: { domain: 'http://domain.example.dev/fb/authCode' } },
RUN 2
#docker-compose -f docker-compose-all.yml logs -t|head
Attaching to oauth_web_1, oauth_core_1, oauth_core-ok_1, oauth_core-fb_1, oauth_oauth_1, oauth_fill-sqls-web_1, oauth_fill-sqls-oauth_1, oauth_web-redis_1, oauth_core-redis_1, oauth_core-mysql_1, oauth_oauth-mysql_1, oauth_web-mysql_1
web_1 | 2016-10-07T06:23:26.013419543Z [06:23:26] Using gulpfile /usr/src/app/gulpfile.js
web_1 | 2016-10-07T06:23:26.015218087Z [06:23:26] Starting 'run'...
web_1 | 2016-10-07T06:23:26.016653267Z [06:23:26] Starting 'templates'...
web_1 | 2016-10-07T06:23:26.026795066Z [06:23:26] Finished 'templates' after 9.26 ms
web_1 | 2016-10-07T06:23:26.027174990Z [06:23:26] Starting 'scripts'...
web_1 | 2016-10-07T06:23:26.040232845Z [06:23:26] Finished 'scripts' after 11 ms
web_1 | 2016-10-07T06:23:26.040447720Z [06:23:26] Starting 'fonts'...
web_1 | 2016-10-07T06:23:26.042183615Z [06:23:26] Finished 'fonts' after 1.31 ms
web_1 | 2016-10-07T06:23:26.042293578Z [06:23:26] Starting 'images'...
As we can see not only docker-compose logs command have logs line order non-persisting, it also mixes up times from different containers. Trying to understand what’s going on through these logs could be a task for a masochist.
But there’s a simple solution, linux has sort command for that. And while constantly typing in commands and their arguments might help learning them by heart it’s inconvenient for everyday tasks. So, why not have a prepared bash script for that.
I hope you have your ~/bin in your PATH, so simply download that to ~/bin folder, set chmod a+x ~/bin/dcsl and enjoy.
The name comes from “Docker Compose Sorted Logs”, so it’s easy to remember. The usage is simple, yet powerful. The downside is that doesn’t work with the follow logs mode.
Usage:
#dcsl -h
Input piped docker-compose logs -t, or a file created from this command, to show logs lines sorted by time.
Usage:
dcsl [-h|--help] - this message
dcsl - runs default docker-compose logs -t and sorts'em
docker-compose logs -t|dcsl - pipe logs to this command
dcsl my-compose.log - or choose file with logs to display
Gist is here, welcome to improve: