search

umputun / docker-logger

Logs collector for docker
MIT License
246 stars 37 forks source link

After restarting the container, all records are logged twice #21

Closed glmars closed 5 years ago

glmars commented 5 years ago

docker restart [my container name] leads to all records are logged twice.

I suppose, two events start + restart are cause of this problem.

This is output of docker events --filter 'container=[my container name]':

2019-06-14T17:37:51.073152530+07:00 container kill 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b (com.docker.compose.config-hash=27db521962a7ab8da02b7af15bb23cff77bad720769ebaddac7e886d291756e5, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=[my project name], com.docker.compose.service=[my service name], com.docker.compose.version=1.17.0, image=openjdk:8u151-jre-slim, name=[my container name], signal=15)
2019-06-14T17:37:51.928043548+07:00 container die 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b (com.docker.compose.config-hash=27db521962a7ab8da02b7af15bb23cff77bad720769ebaddac7e886d291756e5, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=[my project name], com.docker.compose.service=[my service name], com.docker.compose.version=1.17.0, exitCode=143, image=openjdk:8u151-jre-slim, name=[my container name])
2019-06-14T17:37:52.151926158+07:00 container stop 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b (com.docker.compose.config-hash=27db521962a7ab8da02b7af15bb23cff77bad720769ebaddac7e886d291756e5, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=[my project name], com.docker.compose.service=[my service name], com.docker.compose.version=1.17.0, image=openjdk:8u151-jre-slim, name=[my container name])
2019-06-14T17:37:52.634706721+07:00 container start 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b (com.docker.compose.config-hash=27db521962a7ab8da02b7af15bb23cff77bad720769ebaddac7e886d291756e5, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=[my project name], com.docker.compose.service=[my service name], com.docker.compose.version=1.17.0, image=openjdk:8u151-jre-slim, name=[my container name])
2019-06-14T17:37:52.635993651+07:00 container restart 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b (com.docker.compose.config-hash=27db521962a7ab8da02b7af15bb23cff77bad720769ebaddac7e886d291756e5, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=[my project name], com.docker.compose.service=[my service name], com.docker.compose.version=1.17.0, image=openjdk:8u151-jre-slim, name=[my container name])

This is log of docker-logger container:

2019/06/14 10:37:51.928 [INFO]  new event {ContainerID:29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b ContainerName:[my container name] Group: TS:2019-07-02 12:06:19.928043548 +0000 UTC Status:false} 
2019/06/14 10:37:51.928 [WARN]  stream from 29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b terminated with error context canceled                                                                    
2019/06/14 10:37:52.152 [INFO]  new event {ContainerID:29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b ContainerName:[my container name] Group: TS:2019-07-02 12:06:20.151926158 +0000 UTC Status:false} 
2019/06/14 10:37:52.635 [INFO]  new event {ContainerID:29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b ContainerName:[my container name] Group: TS:2019-07-02 12:06:20.634706721 +0000 UTC Status:true}  
2019/06/14 10:37:52.635 [INFO]  loggers created for logs/[my container name].log, max.size=10M, max.files=10, max.days=30                                                                                                 
2019/06/14 10:37:52.635 [INFO]  start log streamer for [my container name]                                                                                                                                                
2019/06/14 10:37:52.636 [INFO]  new event {ContainerID:29b0325002d7d22a9b3ea886cb0e13439c67218c3b8259737b3ca16e1fb17a1b ContainerName:[my container name] Group: TS:2019-07-02 12:06:20.635993651 +0000 UTC Status:true}  
2019/06/14 10:37:52.637 [INFO]  loggers created for logs/[my container name].log, max.size=10M, max.files=10, max.days=30                                                                                                 
2019/06/14 10:37:52.637 [INFO]  start log streamer for [my container name]
umputun commented 5 years ago

can you give me more details about the environment (OS, docker version) you run it? I have never seen dbl logging on restart event in any of the systems I'm running docker-logger on

umputun commented 5 years ago

I can't reproduce it but added a check to avoid dbl streaming. Pls try master and let me know if helped.

glmars commented 5 years ago

Yes, recent changes have helped.

Additional info: the problem is not reproduced every time. For example events & logs from two runs:

2019-06-17T12:29:33.694029740+07:00 container kill d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs, signal=15)
2019-06-17T12:29:33.792732113+07:00 container die d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, exitCode=0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:34.023830805+07:00 container stop d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:34.449760481+07:00 container start d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:34.450009775+07:00 container restart d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)

2019/06/17 05:29:33.793 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:02.792732113 +0000 UTC Status:false}
2019/06/17 05:29:33.794 [WARN]  {logger} stream from d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 terminated with error context canceled
2019/06/17 05:29:34.026 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:03.023830805 +0000 UTC Status:false}
2019/06/17 05:29:34.450 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:03.449760481 +0000 UTC Status:true}
2019/06/17 05:29:34.450 [INFO]  {app} loggers created for logs/webui-ipfs.log and logs/webui-ipfs.log, max.size=10M, max.files=10, max.days=30
2019/06/17 05:29:34.450 [INFO]  {logger} start log streamer for webui-ipfs
2019-06-17T12:29:54.809960170+07:00 container kill d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs, signal=15)
2019-06-17T12:29:54.890460627+07:00 container die d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, exitCode=0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:55.102520106+07:00 container stop d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:55.509882486+07:00 container start d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)
2019-06-17T12:29:55.510195305+07:00 container restart d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 (com.docker.compose.config-hash=1968fe17b9d9e93f512bdd6ae30a84078ebfdc3ff58f1f557e0a8d0a8c45645b, com.docker.compose.container-number=1, com.docker.compose.oneoff=False, com.docker.compose.project=webui, com.docker.compose.service=ipfs, com.docker.compose.version=1.17.0, image=ipfs/go-ipfs:v0.4.14, name=webui-ipfs)

2019/06/17 05:29:54.891 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:23.890460627 +0000 UTC Status:false}
2019/06/17 05:29:54.891 [WARN]  {logger} stream from d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 terminated with error context canceled
2019/06/17 05:29:55.103 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:24.102520106 +0000 UTC Status:false}
2019/06/17 05:29:55.510 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:24.509882486 +0000 UTC Status:true}
2019/06/17 05:29:55.512 [INFO]  {app} loggers created for logs/webui-ipfs.log and logs/webui-ipfs.log, max.size=10M, max.files=10, max.days=30
2019/06/17 05:29:55.512 [INFO]  {logger} start log streamer for webui-ipfs
2019/06/17 05:29:55.534 [INFO]  {discovery} new event {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:24.510195305 +0000 UTC Status:true}
2019/06/17 05:29:55.534 [WARN]  {app} ignore dbl-start {ContainerID:d96bd9ab69b554f53ed29a20929185917a3af29a427e4e1e6be2b13104ed2c11 ContainerName:webui-ipfs Group: TS:2019-07-05 07:02:24.510195305 +0000 UTC Status:true}

My environment: Docker version 17.09.1-ce, build 19e2cf6, Ubuntu 16.04.3 LTS

glmars commented 5 years ago

The same reproduced on: Docker version 18.06.1-ce, build e68fc7a, Ubuntu 18.04.2 LTS

umputun commented 5 years ago

thx. I think we can close the ticket.

Pls note - code from this project was merged into dkll providing the same functionality as docker-logger (dkll agent) plus server mode to collect logs (dkll server) and CLI client to access (dkll client). I'm planning to switch this one into maintenance mode.

glmars commented 5 years ago

Thank you for the quick fix :+1: . Could you publish a new release?

Thanks for info. I'm going to look at dkll :wink:

umputun commented 5 years ago

Could you publish a new release?

done