Compose: logs not sorted by time

[gucki]

docker-compose logs -t seems to output the log entries in random order. It should be possible, best as default, to get a sorted by time output.

[shin-]

Logs are output in the same order they have received from the API, which should be chronological. If you're certain that the logs aren't showing in the same way they do inside your application, you might want to create an issue on https://github.com/moby/moby

[thaJeztah]

If these are logs for a single container being in the wrong order, possibly related to https://github.com/moby/moby/issues/31706

[m-schubert]

@shin- , can we reopen this? When I run docker-compose logs -t (or just docker-compose logs) for a multi-container deploy, I clearly receive logs out of order. Here's a snippet of the logs (3 separate containers):

vpn              | 2019-08-30T06:07:36.147906807Z Fri Aug 30 06:07:36 2019 Validating certificate extended key usage
drillmax_sync    | 2019-07-25T07:37:06.328649066Z 2019-07-25 07:37:06.327767 - INFO - Connecting to 127.0.0.1:10000
drillhub_sync    | 2019-07-27T15:10:05.527034629Z 2019-07-27 15:10:05.526438 - WARNING - Error adding data to database (Error binding parameter 0 - probably unsupported type.), trying again.
vpn              | 2019-08-30T06:07:36.147915309Z Fri Aug 30 06:07:36 2019 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
drillmax_sync    | 2019-07-25T07:37:11.331980052Z 2019-07-25 07:37:11.331181 - INFO - Connecting to 127.0.0.1:10000
drillhub_sync    | 2019-07-27T15:10:34.417148335Z 2019-07-27 15:10:34.416448 - INFO - Archiving data between 2019-07-27 15:08:57.481100 and 2019-07-27 15:09:57.479073.
vpn              | 2019-08-30T06:07:36.147922568Z Fri Aug 30 06:07:36 2019 VERIFY EKU OK
drillmax_sync    | 2019-07-25T07:37:16.334936384Z 2019-07-25 07:37:16.334384 - INFO - Connecting to 127.0.0.1:10000
drillhub_sync    | 2019-07-27T15:10:35.506107023Z 2019-07-27 15:10:35.505604 - INFO - Synchronising 24090 bytes of archived data from 2019-07-27 15:08:57.481100 to 2019-07-27 15:09:57.479073

[rconnaughton]

Agreed, we are also seeing multi-container deploys return logs in an inconsistent order. It appears as though docker-compose logs -f will ensure that _subsequent_ logs are interleaved in the right order, but anything that was logged before the docker-compose logs command was executed is reported in a seemingly nondeterministic order.

ie,

$ docker-compose logs -f -t --tail="2" jappd japid
Attaching to jappd_1, japid_1
jappd_1       | 2019-11-06T18:57:41.056315496Z jappd [INFO] Logout <username>
jappd_1       | 2019-11-06T19:02:36.775814617Z jappd [INFO] Login <username>
japid_1       | 2019-11-06T17:38:08.183852624Z japid [INFO] Booting worker
japid_1       | 2019-11-06T18:57:34.546353640Z japid [WARNING] ValueError('You entered an invalid DOB',)

Leaving the above tailing, additional log lines were generated:

$ docker-compose logs -f -t --tail="2" jappd japid
Attaching to jappd_1, japid_1
jappd_1       | 2019-11-06T18:57:41.056315496Z jappd [INFO] Logout <username>
jappd_1       | 2019-11-06T19:02:36.775814617Z jappd [INFO] Login <username>
japid_1       | 2019-11-06T17:38:08.183852624Z japid [INFO] Booting worker
japid_1       | 2019-11-06T18:57:34.546353640Z japid [WARNING] ValueError('You entered an invalid DOB',)
jappd_1       | 2019-11-06T19:17:55.032596658Z jappd [INFO] Logout <username>
jappd_1       | 2019-11-06T19:18:39.532826408Z jappd [INFO] Login <username>
japid_1       | 2019-11-06T19:18:47.258428862Z japid [WARNING] ValueError('You entered an invalid DOB',)

Then the command was killed and re-executed:

docker-compose logs -f -t --tail="2" jappd japid
Attaching to jappd_1, japid_1
japid_1       | 2019-11-06T18:57:34.546353640Z japid [WARNING] ValueError('You entered an invalid DOB',)
japid_1       | 2019-11-06T19:18:47.258428862Z japid [WARNING] ValueError('You entered an invalid DOB',)
jappd_1       | 2019-11-06T19:17:55.032596658Z jappd [INFO] Logout <username>
jappd_1       | 2019-11-06T19:18:39.532826408Z jappd [INFO] Login <username>

Notice the log lines are now output in a different order than they were originally displayed while tailing.

[gsommavilla]

I am experiencing the same issue.

My docker-compose services have the journald logging driver:

logging:
  driver: journald

docker-compose logs not chronologically ordered

When I print the docker-compose logs, I get some logs which are out of chronological order. In the example below, some logs are out of place (with a difference up to 5 days):

myplace@dev_app12:/opt/docker_data/vi$ docker-compose logs -t --no-color  | less
# ...
app12-backend_1             | 2020-07-03T14:04:08       .858179000Z   tmpFolder: '/tmp',
app12-backend_1             | 2020-07-03T14:04:08.858266000Z   websocketport: '8080',
app12-backend_1             | 2020-07-03T14:04:08.858345000Z   wsApp12Protocol: 'app12-service-communication',
app12-backend_1             | 2020-07-03T14:04:08.858426000Z   wsWAEServerUri: 'ws://webapp-engine',
app12-backend_1             | 2020-07-03T14:04:08.858503000Z   wsWAEServerPort: '8080',
app12-backend_1             | 2020-07-03T14:04:08.858586000Z   wsWAEServerProtocol: 'app12-service-communication' }
app12-backend_1             | 2020-07-03T14:04:08.874457000Z (node:26) DeprecationWarning: collection.ensureIndex is deprecated. Use createIndexes instead.
nginx_1                     | 2020-06-30T07:49:28.831918000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
mongodb_1                   | 2020-07-03T14:14:45.592202000Z 2020-07-03T14:14:45.591+0000 I  NETWORK  [listener] connection accepted from 172.22.0.13:42656 #3 (3 connections now open)
nginx_1                     | 2020-06-30T07:49:31.592645000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
dialog_1                    | 2020-07-03T14:03:36.029317000Z > [email protected] start /usr/src/app
mongodb_1                   | 2020-07-03T14:14:45.592703000Z 2020-07-03T14:14:45.592+0000 I  NETWORK  [conn3] received client metadata from 172.22.0.13:42656 conn3: { driver: { name: "nodejs", version: "3.5.7" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "4.15.0-96-generic" }, platform: "'Node.js v9.11.2, LE (legacy)" }
vi-ext-api-server_1         | 2020-07-06T14:46:06.758416000Z serverConfig:
mongodb_multimedia_files_1  | 2020-06-29T14:35:13.367631000Z 2020-06-29T14:35:13.076+0000 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
nginx_1                     | 2020-06-30T07:49:34.279573000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
cron-file-cleaner_1         | 2020-07-01T14:12:26.107691000Z files to be cleaned are:
dialog_1                    | 2020-07-03T14:03:36.029481000Z > node ./app.js
mongodb_1                   | 2020-07-03T14:14:45.593297000Z 2020-07-03T14:14:45.593+0000 I  SHARDING [conn3] Marking collection Operator_BackEnd.app12s_states as collection version: <unsharded>

journald logs seem fine

If I print the logs with journalctl, the logs seem to be chronologically ordered (I looked though a lot of logs, and they seemed fine).

As an example, I searched the nginx_1 | 2020-06-30T07:49:28 log (which is out of place in the example above), and I found that it is ok with journald:

myplace@dev_app12:/opt/docker_data/vi$ sudo journalctl -b  -u docker -o short-iso --utc --since "171 hours ago" | less
# ...
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_vi-ext-api-server_1/d434b7469183[1103]:   rejectUnauthorized: false
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_vi-ext-api-server_1/d434b7469183[1103]: }
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_webapp-engine_1/61cfdaf265a5[1103]: Redirect to Operator get_sessions_state
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_nginx_1/07e2c2de7c59[1103]: nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_vi-ext-api-server_1/d434b7469183[1103]: statusCode: 200
2020-06-30T07:49:28+0000 dev_app12.myplace.lan vi_vi-ext-api-server_1/d434b7469183[1103]: INFO: response received

[thaJeztah]

@gsommavilla the journald logs are written to a single file as they arrive, whereas docker-compose logs collects logs from each container's logs. If I read your example correctly, in the output of docker-compose logs, logs for each container is in chronological order, but logs of the containers _combined_ is not in "absolute" order. Here's the output when ordered per-container;

app12-backend_1             | 2020-07-03T14:04:08       .858179000Z   tmpFolder: '/tmp',
app12-backend_1             | 2020-07-03T14:04:08.858266000Z   websocketport: '8080',
app12-backend_1             | 2020-07-03T14:04:08.858345000Z   wsApp12Protocol: 'app12-service-communication',
app12-backend_1             | 2020-07-03T14:04:08.858426000Z   wsWAEServerUri: 'ws://webapp-engine',
app12-backend_1             | 2020-07-03T14:04:08.858503000Z   wsWAEServerPort: '8080',
app12-backend_1             | 2020-07-03T14:04:08.858586000Z   wsWAEServerProtocol: 'app12-service-communication' }
app12-backend_1             | 2020-07-03T14:04:08.874457000Z (node:26) DeprecationWarning: collection.ensureIndex is deprecated. Use createIndexes instead.
cron-file-cleaner_1         | 2020-07-01T14:12:26.107691000Z files to be cleaned are:
dialog_1                    | 2020-07-03T14:03:36.029317000Z > [email protected] start /usr/src/app
dialog_1                    | 2020-07-03T14:03:36.029481000Z > node ./app.js
mongodb_1                   | 2020-07-03T14:14:45.592202000Z 2020-07-03T14:14:45.591+0000 I  NETWORK  [listener] connection accepted from 172.22.0.13:42656 #3 (3 connections now open)
mongodb_1                   | 2020-07-03T14:14:45.592703000Z 2020-07-03T14:14:45.592+0000 I  NETWORK  [conn3] received client metadata from 172.22.0.13:42656 conn3: { driver: { name: "nodejs", version: "3.5.7" }, os: { type: "Linux", name: "linux", architecture: "x64", version: "4.15.0-96-generic" }, platform: "'Node.js v9.11.2, LE (legacy)" }
mongodb_1                   | 2020-07-03T14:14:45.593297000Z 2020-07-03T14:14:45.593+0000 I  SHARDING [conn3] Marking collection Operator_BackEnd.app12s_states as collection version: <unsharded>
mongodb_multimedia_files_1  | 2020-06-29T14:35:13.367631000Z 2020-06-29T14:35:13.076+0000 I  CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
nginx_1                     | 2020-06-30T07:49:28.831918000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
nginx_1                     | 2020-06-30T07:49:31.592645000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
nginx_1                     | 2020-06-30T07:49:34.279573000Z nginx: [emerg] open() "/etc/mime.types" failed (2: No such file or directory) in /etc/nginx/conf.d/default.conf:4
vi-ext-api-server_1         | 2020-07-06T14:46:06.758416000Z serverConfig:

Unfortunately, I don't think it's really possible to resolve that (at least, not without causing a big overhead). Logs for each container is stored separate, and is fetched using a separate API call/returned as a separate stream. Docker Compose prints those logs as they arrive, which means that logs for container "B" may arrive later than container "A".

The only way to solve that would be to buffer _all_ logs in memory, wait for all logs to arrive from the API, and then sort the results.

You can probably achieve that if you sort the results on the time column, something like:

docker-compose logs -t  --no-color | sort -u -k 3 | less

[lucasvc]

Maybe I'm a bit naïve, but your line @thaJeztah

Logs for each container is stored separate, and is fetched using a separate API call/returned as a separate stream.

Would be a so big overhead to add an extra stream for all started containers logs?
For sure I miss something (started later containers?) as I'm not Docker nor Compose expert. But having all containers logs in the received order, would be a really good improvement when debugging.