Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Reduce number of log messages for Docker pull #24

Closed
MichaelRoeder opened this issue Apr 5, 2017 · 4 comments
Closed

Reduce number of log messages for Docker pull #24

MichaelRoeder opened this issue Apr 5, 2017 · 4 comments
Assignees
@JonathanHuthmann
Labels
component: controller priority: low type: enhancement

Comments

@MichaelRoeder
Copy link
Contributor

Problem

When the platform pulls images, it uses the default logging of the Docker client library. However, this behaves similar to the output of Docker and shows the current status of the downlod:

...
2017-04-05 11:08:03,925 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[================================>                  ]  67.4 MB/104.4 MB, progressDetail=ProgressDetail{current=67403776, start=0, total=104428575}}>
2017-04-05 11:08:04,171 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=================================>                 ] 69.63 MB/104.4 MB, progressDetail=ProgressDetail{current=69632000, start=0, total=104428575}}>
2017-04-05 11:08:04,303 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[==================================>                ]  71.3 MB/104.4 MB, progressDetail=ProgressDetail{current=71303168, start=0, total=104428575}}>
2017-04-05 11:08:04,413 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[==================================>                ] 72.42 MB/104.4 MB, progressDetail=ProgressDetail{current=72417280, start=0, total=104428575}}>
2017-04-05 11:08:04,553 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[===================================>               ] 74.09 MB/104.4 MB, progressDetail=ProgressDetail{current=74088448, start=0, total=104428575}}>
2017-04-05 11:08:04,664 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[====================================>              ] 75.76 MB/104.4 MB, progressDetail=ProgressDetail{current=75759616, start=0, total=104428575}}>
2017-04-05 11:08:04,769 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[====================================>              ] 76.87 MB/104.4 MB, progressDetail=ProgressDetail{current=76873728, start=0, total=104428575}}>
2017-04-05 11:08:04,955 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=====================================>             ] 77.99 MB/104.4 MB, progressDetail=ProgressDetail{current=77987840, start=0, total=104428575}}>
2017-04-05 11:08:05,115 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=====================================>             ]  79.1 MB/104.4 MB, progressDetail=ProgressDetail{current=79101952, start=0, total=104428575}}>
2017-04-05 11:08:05,219 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[======================================>            ] 80.22 MB/104.4 MB, progressDetail=ProgressDetail{current=80216064, start=0, total=104428575}}>
2017-04-05 11:08:05,348 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[======================================>            ] 80.77 MB/104.4 MB, progressDetail=ProgressDetail{current=80773120, start=0, total=104428575}}>
2017-04-05 11:08:05,492 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=======================================>           ] 81.89 MB/104.4 MB, progressDetail=ProgressDetail{current=81887232, start=0, total=104428575}}>
2017-04-05 11:08:05,594 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=========================================>         ] 85.79 MB/104.4 MB, progressDetail=ProgressDetail{current=85786624, start=0, total=104428575}}>
2017-04-05 11:08:05,696 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[============================================>      ] 92.47 MB/104.4 MB, progressDetail=ProgressDetail{current=92471296, start=0, total=104428575}}>
2017-04-05 11:08:05,801 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[================================================>  ] 101.4 MB/104.4 MB, progressDetail=ProgressDetail{current=101384192, start=0, total=104428575}}>
2017-04-05 11:08:05,925 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[=================================================> ] 104.2 MB/104.4 MB, progressDetail=ProgressDetail{current=104169472, start=0, total=104428575}}>
2017-04-05 11:08:05,962 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Extracting, stream=null, error=null, progress=[==================================================>] 104.4 MB/104.4 MB, progressDetail=ProgressDetail{current=104428575, start=0, total=104428575}}>
2017-04-05 11:08:06,175 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=713c891b8f9f, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:06,272 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[>                                                  ] 196.6 kB/18.47 MB, progressDetail=ProgressDetail{current=196608, start=0, total=18469948}}>
2017-04-05 11:08:06,377 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[====>                                              ] 1.769 MB/18.47 MB, progressDetail=ProgressDetail{current=1769472, start=0, total=18469948}}>
2017-04-05 11:08:06,484 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[=========>                                         ] 3.539 MB/18.47 MB, progressDetail=ProgressDetail{current=3538944, start=0, total=18469948}}>
2017-04-05 11:08:06,585 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[============>                                      ] 4.719 MB/18.47 MB, progressDetail=ProgressDetail{current=4718592, start=0, total=18469948}}>
2017-04-05 11:08:06,689 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[=================>                                 ] 6.488 MB/18.47 MB, progressDetail=ProgressDetail{current=6488064, start=0, total=18469948}}>
2017-04-05 11:08:06,790 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[=====================>                             ] 8.061 MB/18.47 MB, progressDetail=ProgressDetail{current=8060928, start=0, total=18469948}}>
2017-04-05 11:08:06,904 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[==========================>                        ] 9.634 MB/18.47 MB, progressDetail=ProgressDetail{current=9633792, start=0, total=18469948}}>
2017-04-05 11:08:07,014 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[=============================>                     ] 10.81 MB/18.47 MB, progressDetail=ProgressDetail{current=10813440, start=0, total=18469948}}>
2017-04-05 11:08:07,117 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[================================>                  ] 12.19 MB/18.47 MB, progressDetail=ProgressDetail{current=12189696, start=0, total=18469948}}>
2017-04-05 11:08:07,224 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[====================================>              ] 13.57 MB/18.47 MB, progressDetail=ProgressDetail{current=13565952, start=0, total=18469948}}>
2017-04-05 11:08:07,339 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[========================================>          ] 15.14 MB/18.47 MB, progressDetail=ProgressDetail{current=15138816, start=0, total=18469948}}>
2017-04-05 11:08:07,444 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[============================================>      ] 16.52 MB/18.47 MB, progressDetail=ProgressDetail{current=16515072, start=0, total=18469948}}>
2017-04-05 11:08:07,554 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[================================================>  ] 17.89 MB/18.47 MB, progressDetail=ProgressDetail{current=17891328, start=0, total=18469948}}>
2017-04-05 11:08:07,615 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[==================================================>] 18.47 MB/18.47 MB, progressDetail=ProgressDetail{current=18469948, start=0, total=18469948}}>
2017-04-05 11:08:07,642 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Extracting, stream=null, error=null, progress=[==================================================>] 18.47 MB/18.47 MB, progressDetail=ProgressDetail{current=18469948, start=0, total=18469948}}>
2017-04-05 11:08:08,134 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=ca1b4e9e252d, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:08,143 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=415c99e12fe5, status=Extracting, stream=null, error=null, progress=[==================================================>] 2.917 kB/2.917 kB, progressDetail=ProgressDetail{current=2917, start=0, total=2917}}>
2017-04-05 11:08:08,155 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=415c99e12fe5, status=Extracting, stream=null, error=null, progress=[==================================================>] 2.917 kB/2.917 kB, progressDetail=ProgressDetail{current=2917, start=0, total=2917}}>
2017-04-05 11:08:08,271 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=415c99e12fe5, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:08,279 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=f1e0080d27b3, status=Extracting, stream=null, error=null, progress=[==================================================>]    650 B/650 B, progressDetail=ProgressDetail{current=650, start=0, total=650}}>
2017-04-05 11:08:08,282 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=f1e0080d27b3, status=Extracting, stream=null, error=null, progress=[==================================================>]    650 B/650 B, progressDetail=ProgressDetail{current=650, start=0, total=650}}>
2017-04-05 11:08:08,363 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=f1e0080d27b3, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:08,366 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=bcf987553b74, status=Extracting, stream=null, error=null, progress=[==================================================>]    253 B/253 B, progressDetail=ProgressDetail{current=253, start=0, total=253}}>
2017-04-05 11:08:08,371 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=bcf987553b74, status=Extracting, stream=null, error=null, progress=[==================================================>]    253 B/253 B, progressDetail=ProgressDetail{current=253, start=0, total=253}}>
2017-04-05 11:08:08,472 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=bcf987553b74, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:08,480 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=b5072ee83ce1, status=Extracting, stream=null, error=null, progress=[==================================================>]    664 B/664 B, progressDetail=ProgressDetail{current=664, start=0, total=664}}>
2017-04-05 11:08:08,486 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=b5072ee83ce1, status=Extracting, stream=null, error=null, progress=[==================================================>]    664 B/664 B, progressDetail=ProgressDetail{current=664, start=0, total=664}}>
2017-04-05 11:08:08,623 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=b5072ee83ce1, status=Pull complete, stream=null, error=null, progress=null, progressDetail=ProgressDetail{current=0, start=0, total=0}}>
2017-04-05 11:08:08,631 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=null, status=Digest: sha256:5b9da3cd46849e3528ba5b9770c13461f5d5563f079d07d1495899761179788b, stream=null, error=null, progress=null, progressDetail=null}>
2017-04-05 11:08:08,635 INFO [com.spotify.docker.client.LoggingPullHandler] - <pull tenforce/virtuoso: ProgressMessage{id=null, status=Status: Downloaded newer image for tenforce/virtuoso, stream=null, error=null, progress=null, progressDetail=null}>
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8

This becomes a problem especially on a Docker swarm cluster where every node generates this huge amount of log messages.

Proposed solution

Create a small class implementing the com.spotify.docker.client.ProgressHandler interface and log only those messages, that we are interested in:

  • Start pulling (log level INFO)
  • Pull successful (log level INFO)
  • Pull was not needed (log level INFO)
  • Error during pull (log level ERROR)

Use this class when pulling images https://github.com/hobbit-project/platform/blob/master/platform-controller/src/main/java/org/hobbit/controller/docker/ContainerManagerImpl.java#L216
@MichaelRoeder
Copy link
Contributor Author

addressed with 1513d6e

@MichaelRoeder
Copy link
Contributor Author

The current fix does only work for images that are pulled before an experiment starts.

@MichaelRoeder MichaelRoeder mentioned this issue Feb 28, 2018
Merged
MichaelRoeder added a commit that referenced this issue Feb 28, 2018
@MichaelRoeder
Merge pull request #227 from hobbit-project/develop
e4b93fb 
Developed version 2.0.0 of the platform. Moved to Docker swarm (using Docker services instead of docker-compose) (#100, #158, makes #24 obsolete). Updated VOS version and made sure that future updates of the version can be done easily (#48). Added cluster health checks (#97). Added support for gathering statistics about the usage of resources (#98). Added the visualization of complex data as diagrams (#125). Cleaned up deployment process (#162).
@denkv
Copy link
Collaborator

denkv commented Apr 24, 2018

The current fix does only work for images that are pulled before an experiment starts.

There certainly are cases when some image is being pulled with excess log messages.

screenshot-2018-04-24 15 06 57 00 00-bm0fgbbna7
screenshot-2018-04-24 15 11 48 00 00-1iiejnbs7d

@denkv denkv reopened this Apr 24, 2018
@MichaelRoeder MichaelRoeder mentioned this issue Apr 24, 2018
Closed
@MichaelRoeder
Copy link
Contributor Author

Can be solved by solving #274

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@JonathanHuthmann JonathanHuthmann

Labels
component: controller priority: low type: enhancement
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@MichaelRoeder @JonathanHuthmann @denkv