search

bblfsh / bblfshd

A self-hosted server for source code parsing
https://doc.bblf.sh
GNU General Public License v3.0
358 stars 54 forks source link

Logs: missing "container stopped" records #98

Closed vmarkovtsev closed 7 years ago

vmarkovtsev commented 7 years ago

This is an example of a bblfsh server's logs under high load:

time="2017-09-11T10:12:06Z" level=info msg="parsing HomePageFragment2.java (28041 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing OnlineFragment.java (6132 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing PersonCenterFragment.java (134 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing RankFragment.java (7577 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SDW513VN0ZZSS3PES6N4)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing RelevantVideoFragment.java (135 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing SubareaFragment.java (2345 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing VideoInfoFragment.java (9443 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SE047BJAT9SPFDAWW33Y)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing AreaItem.java (349 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing BannerItem.java (708 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing GameItem.java (499 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing OnlineVideo.java (806 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing Page.java (494 bytes)" 
time="2017-09-11T10:12:06Z" level=info msg="parsing User.java (2211 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing Video.java (3521 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing VideoItem.java (2590 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SE443RDZYB2WRGX9XZA2)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing ArrayUtils.java (1166 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing CompressionTools.java (2928 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing Constants.java (3866 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing DeviceUtils.java (7551 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SE8SKJ4YE9PH84NVX79P)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing DownUtil.java (4623 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SEDFX9589EGJZA0Y7S7C)" 
time="2017-09-11T10:12:07Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SEHXZ69FWJKYBC579B59)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing FileUitl.java (3662 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing FileUtils.java (11263 bytes)" 
time="2017-09-11T10:12:07Z" level=info msg="parsing FractionalTouchDelegate.java (5312 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing HttpDownloader.java (5836 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing HttpUtil.java (15548 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing ImageUtils.java (10043 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing IntentHelper.java (3262 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing JsoupUtil.java (833 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing Logger.java (2561 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing MediaUtils.java (9612 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing MultiMemberGZIPInputStream.java (3315 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing PreferenceUtils.java (4323 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing StringUtils.java (8705 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing ToastUtils.java (2011 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing URLUtil.java (11974 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing XmlReaderHelper.java (3897 bytes)" 
time="2017-09-11T10:12:08Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SG0XZ0FG1PV9DG4WKJM2)" 
time="2017-09-11T10:12:08Z" level=info msg="parsing ApplicationUtils.java (3928 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing CircleImageView.java (7305 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing CommonGestures.java (4955 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing FileUtils.java (11308 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SG51GZQQN4R9SY4B798W)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing LeftSliderLayout.java (13298 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing MediaController.java (23956 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SG97GW4TBW4NWB7FPB94)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing PlayerService.java (15043 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SGDF49AZFENEC93EPWYK)" 
time="2017-09-11T10:12:09Z" level=info msg="parsing PullToZoomListView.java (9210 bytes)" 
time="2017-09-11T10:12:09Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SGJ056PZ6VM9P9DB6SE3)" 
time="2017-09-11T10:12:09Z" level=info msg="container started bblfsh/java-driver:latest (01BSR6SGPG5NQZN6H0C6RBSHCY)" 
time="2017-09-11T10:12:10Z" level=info msg="parsing VP.java (2207 bytes)" 
time="2017-09-11T10:12:10Z" level=info msg="parsing VideoView.java (4721 bytes)" 
time="2017-09-11T10:12:12Z" level=info msg="parsing ScreenCaptureImageActivity.java (9608 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing NotFoundException.java (546 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing RestError.java (4171 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing NotImplementedException.java (565 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing CrudService.java (1943 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing CrudServiceImpl.java (3271 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing package-info.java (62 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing ClassUtils.java (1725 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing PostInitialize.java (811 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing package-info.java (59 bytes)" 
time="2017-09-11T10:12:13Z" level=info msg="parsing PostInitializerRunner.java (7054 bytes)"

I miss the message when containers stop/die. I assume they are written under DEBUG log level, but the level should be INFO since you report "started" messages under INFO. Thus currently it is not possible to estimate the average lifetime of a container.

Besides

I see that containers are spawned like crazy. It's been 17 hours since the torture started. Thus I have an impression that the scaling algorithm went wild. Are there any cold period tunables? How can I debug the reason why it happens? Will DEBUG log level help?

I propose to add the reason why the container is killed or restarted - e.g. a scaling decision or a panic/segfault. No need to be verbose, I want smth like

time="2017-09-11T10:12:09Z" level=info msg="container stopped bblfsh/java-driver:latest (01BSR6SG97GW4TBW4NWB7FPB94) - oops" time="2017-09-11T10:12:09Z" level=info msg="container stopped bblfsh/java-driver:latest (01BSR6SG97GW4TBW4NWB7FPB94) - scaling"

mcuadros commented 7 years ago

Fixed by https://github.com/bblfsh/server/pull/106

vmarkovtsev commented 7 years ago

Thank you!