SyncThread exit issues

SyncThread exit issues

[Richard Purdie]

Hi All,

Its taken quite a bit of debugging and going around in circles but I'm
now 99% sure the remaining "hung" bitbake issues are related to the
SyncThread. It is exiting correctly but taking far too long to do so.
The bitbake-cookerdaemon log for a recent failure is shown below but
the key section is this:

622524 16:21:48.768140 Exiting
622524 16:23:22.923871 Original lockfile
contents: ['622524\n']

i.e. at exit bitbake went AWOL for 94s. This is longer than the 60s 
connection timeout so this is why other tests failed. Earlier lines in the log clearly show the SyncThread had not finished.

I'm not really sure what to do about this, presumably its due to high 
IO load on on the autobuilders.

I wanted to mention it to show that we are at least able to clearly 
identify the cause of the rare test failures and the logs are doing a 
better job of capturing what is going on.

(https://autobuilder.yoctoproject.org/typhoon/#/builders/86/builds/1352 was the build that failed this corresponds to)

Cheers,

Richard

622524 16:21:41.452474 --- Starting bitbake server pid 622524 at 2020-09-12 16:21:41.452387 ---
622524 16:21:41.473890 Started bitbake server pid 622524
622524 16:21:41.474361 Entering server connection loop
622524 16:21:41.474703 Accepting [<socket.socket fd=6, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=bitbake.sock>] ([])
622524 16:21:41.474800 Processing Client
622524 16:21:41.474910 Connecting Client
622524 16:21:41.475765 Running command ['setFeatures', [2]]
622524 16:21:41.477016 Command Completed
622524 16:21:41.477274 Running command ['updateConfig', {'abort': True, 'force': False, 'invalidate_stamp': None, 'dry_run': False, 'dump_signatures': [], 'extra_assume_provided': [], 'profile': False, 'prefile': [], 'postfile': [], 'server_timeout': None, 'nosetscene': False, 'setsceneonly': False, 'skipsetscene': False, 'runall': None, 'runonly': None, 'writeeventlog': None, 'build_verbose_shell': False, 'build_verbose_stdout': False, 'default_loglevel': 20, 'debug_domains': {}}, {'SHELL': '/bin/bash', 'BB_LOGCONFIG': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103/../bitbake/contrib/autobuilderlog.json', 'PWD': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'LOGNAME': 'pokybuild', 'ftp_proxy': 'http://proxy.yocto.io:5187/', 'HOME': '/home/pokybuild', 'BBPATH': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'BB_ENV_EXTRAWHITE': 'ALL_PROXY BBPATH_EXTRA BB_LOGCONFIG BB_NO_NETWORK BB_NUMBER_THREADS BB_SETSCENE_ENFORCE BB_SRCREV_POLICY DISTRO FTPS_PROXY FTP_PROXY GIT_PROXY_COMMAND HTTPS_PROXY HTTP_PROXY MACHINE NO_PROXY PARALLEL_MAKE SCREENDIR SDKMACHINE SOCKS5_PASSWD SOCKS5_USER SSH_AGENT_PID SSH_AUTH_SOCK STAMPS_DIR TCLIBC TCMODE all_proxy ftp_proxy ftps_proxy http_proxy https_proxy no_proxy ', 'USER': 'pokybuild', 'FTP_PROXY': 'http://proxy.yocto.io:5187/', 'PATH': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/scripts:/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin:/home/pokybuild/.local/bin:/home/pokybuild/bin:/usr/lib64/ccache:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin', 'LC_ALL': 'en_US.UTF-8', 'HISTCONTROL': 'ignoredups', 'HISTSIZE': '1000', 'HOSTNAME': 'fedora31-ty-1', 'ABHELPER_JSON': 'config.json /home/pokybuild/config-local.json', '_': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin/bitbake', 'LANG': 'en_US.UTF-8', 'LS_COLORS': 'rs=0:di=38;5;33:ln=38;5;51:mh=00:pi=40;38;5;11:so=38;5;13:do=38;5;5:bd=48;5;232;38;5;11:cd=48;5;232;38;5;3:or=48;5;232;38;5;9:mi=01;37;41:su=48;5;196;38;5;15:sg=48;5;11;38;5;16:ca=48;5;196;38;5;226:tw=48;5;10;38;5;16:ow=48;5;10;38;5;21:st=48;5;21;38;5;15:ex=38;5;40:*.tar=38;5;9:*.tgz=38;5;9:*.arc=38;5;9:*.arj=38;5;9:*.taz=38;5;9:*.lha=38;5;9:*.lz4=38;5;9:*.lzh=38;5;9:*.lzma=38;5;9:*.tlz=38;5;9:*.txz=38;5;9:*.tzo=38;5;9:*.t7z=38;5;9:*.zip=38;5;9:*.z=38;5;9:*.dz=38;5;9:*.gz=38;5;9:*.lrz=38;5;9:*.lz=38;5;9:*.lzo=38;5;9:*.xz=38;5;9:*.zst=38;5;9:*.tzst=38;5;9:*.bz2=38;5;9:*.bz=38;5;9:*.tbz=38;5;9:*.tbz2=38;5;9:*.tz=38;5;9:*.deb=38;5;9:*.rpm=38;5;9:*.jar=38;5;9:*.war=38;5;9:*.ear=38;5;9:*.sar=38;5;9:*.rar=38;5;9:*.alz=38;5;9:*.ace=38;5;9:*.zoo=38;5;9:*.cpio=38;5;9:*.7z=38;5;9:*.rz=38;5;9:*.cab=38;5;9:*.wim=38;5;9:*.swm=38;5;9:*.dwm=38;5;9:*.esd=38;5;9:*.jpg=38;5;13:*.jpeg=38;5;13:*.mjpg=38;5;13:*.mjpeg=38;5;13:*.gif=38;5;13:*.bmp=38;5;13:*.pbm=38;5;13:*.pgm=38;5;13:*.ppm=38;5;13:*.tga=38;5;13:*.xbm=38;5;13:*.xpm=38;5;13:*.tif=38;5;13:*.tiff=38;5;13:*.png=38;5;13:*.svg=38;5;13:*.svgz=38;5;13:*.mng=38;5;13:*.pcx=38;5;13:*.mov=38;5;13:*.mpg=38;5;13:*.mpeg=38;5;13:*.m2v=38;5;13:*.mkv=38;5;13:*.webm=38;5;13:*.ogm=38;5;13:*.mp4=38;5;13:*.m4v=38;5;13:*.mp4v=38;5;13:*.vob=38;5;13:*.qt=38;5;13:*.nuv=38;5;13:*.wmv=38;5;13:*.asf=38;5;13:*.rm=38;5;13:*.rmvb=38;5;13:*.flc=38;5;13:*.avi=38;5;13:*.fli=38;5;13:*.flv=38;5;13:*.gl=38;5;13:*.dl=38;5;13:*.xcf=38;5;13:*.xwd=38;5;13:*.yuv=38;5;13:*.cgm=38;5;13:*.emf=38;5;13:*.ogv=38;5;13:*.ogx=38;5;13:*.aac=38;5;45:*.au=38;5;45:*.flac=38;5;45:*.m4a=38;5;45:*.mid=38;5;45:*.midi=38;5;45:*.mka=38;5;45:*.mp3=38;5;45:*.mpc=38;5;45:*.ogg=38;5;45:*.ra=38;5;45:*.wav=38;5;45:*.oga=38;5;45:*.opus=38;5;45:*.spx=38;5;45:*.xspf=38;5;45:', 'OEQA_DEBUGGING_SAVED_OUTPUT': '/srv/autobuilder/autobuilder.yoctoproject.org/pub/repro-fail/', 'TERM': 'xterm-256color', 'SCRIPTSDIR': '/home/pokybuild/yocto-worker/oe-selftest-fedora/yocto-autobuilder-helper/scripts', 'LESSOPEN': '||/usr/bin/lesspipe.sh %s', 'DISPLAY': ':1', 'SHLVL': '2', 'BUILDDIR': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'MAIL': '/var/spool/mail/pokybuild', 'OLDPWD': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build'}, ['/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin/bitbake', '-e', 'mtools-native']]
622524 16:21:42.182550 Command Completed
622524 16:21:42.183214 Running command ['getVariable', 'BBINCLUDELOGS']
622524 16:21:42.183776 Command Completed
622524 16:21:42.184081 Running command ['getVariable', 'BBINCLUDELOGS_LINES']
622524 16:21:42.184568 Command Completed
622524 16:21:42.184851 Running command ['getSetVariable', 'BB_CONSOLELOG']
622524 16:21:42.185600 Command Completed
622524 16:21:42.185880 Running command ['getSetVariable', 'BB_LOGCONFIG']
622524 16:21:42.189834 Command Completed
622524 16:21:42.190294 Running command ['getUIHandlerNum']
622524 16:21:42.190807 Command Completed
622524 16:21:42.191152 Running command ['setEventMask', 1, 20, {'BitBake.SigGen.HashEquiv': 19, 'BitBake.RunQueue.HashEquiv': 19}, ['bb.runqueue.runQueueExitWait', 'bb.event.LogExecTTY', 'logging.LogRecord', 'bb.build.TaskFailed', 'bb.build.TaskBase', 'bb.event.ParseStarted', 'bb.event.ParseProgress', 'bb.event.ParseCompleted', 'bb.event.CacheLoadStarted', 'bb.event.CacheLoadProgress', 'bb.event.CacheLoadCompleted', 'bb.command.CommandFailed', 'bb.command.CommandExit', 'bb.command.CommandCompleted', 'bb.cooker.CookerExit', 'bb.event.MultipleProviders', 'bb.event.NoProvider', 'bb.runqueue.sceneQueueTaskStarted', 'bb.runqueue.runQueueTaskStarted', 'bb.runqueue.runQueueTaskFailed', 'bb.runqueue.sceneQueueTaskFailed', 'bb.event.BuildBase', 'bb.build.TaskStarted', 'bb.build.TaskSucceeded', 'bb.build.TaskFailedSilent', 'bb.build.TaskProgress', 'bb.event.ProcessStarted', 'bb.event.ProcessProgress', 'bb.event.ProcessFinished']]
622524 16:21:42.191650 Command Completed
622524 16:21:42.191940 Running command ['getVariable', 'BB_DEFAULT_TASK']
622524 16:21:42.192446 Command Completed
622524 16:21:42.192733 Running command ['setConfig', 'cmd', 'build']
622524 16:21:42.193208 Command Completed
622524 16:21:42.193482 Running command ['showEnvironmentTarget', ['mtools-native']]
622524 16:21:42.193909 Command Completed
622524 16:21:48.666380 Processing Client
622524 16:21:48.666545 Disconnecting Client
622524 16:21:48.667019 No timeout, exiting.
622524 16:21:48.768024 More than one thread left?: [<_MainThread(MainThread, started 139792596600512)>, <Thread(SyncThread, started 139792284829440)>]
622524 16:21:48.768140 Exiting
622524 16:23:22.923871 Original lockfile contents: ['622524\n']
622524 16:23:22.924338 Exiting as we could obtain the lock
741306 16:23:26.043623 --- Starting bitbake server pid 741306 at 2020-09-12 16:23:26.043566 ---
741306 16:23:26.056743 Started bitbake server pid 741306
741306 16:23:26.057200 Entering server connection loop
741306 16:23:26.058629 Accepting [<socket.socket fd=6, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=bitbake.sock>] ([])
741306 16:23:26.059628 Processing Client
741306 16:23:26.059740 Connecting Client
741306 16:23:26.060568 Running command ['setFeatures', [2, 1]]
741306 16:23:26.060944 Command Completed
741306 16:23:26.062100 Running command ['updateConfig', {'abort': True, 'force': False, 'invalidate_stamp': None, 'dry_run': False, 'dump_signatures': [], 'extra_assume_provided': [], 'profile': False, 'prefile': [], 'postfile': [], 'server_timeout': None, 'nosetscene': False, 'setsceneonly': False, 'skipsetscene': False, 'runall': None, 'runonly': None, 'writeeventlog': None, 'build_verbose_shell': False, 'build_verbose_stdout': False, 'default_loglevel': 20, 'debug_domains': {}}, {'SHELL': '/bin/bash', 'BB_LOGCONFIG': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103/../bitbake/contrib/autobuilderlog.json', 'PWD': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'LOGNAME': 'pokybuild', 'ftp_proxy': 'http://proxy.yocto.io:5187/', 'HOME': '/home/pokybuild', 'BBPATH': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'BB_ENV_EXTRAWHITE': 'ALL_PROXY BBPATH_EXTRA BB_LOGCONFIG BB_NO_NETWORK BB_NUMBER_THREADS BB_SETSCENE_ENFORCE BB_SRCREV_POLICY DISTRO FTPS_PROXY FTP_PROXY GIT_PROXY_COMMAND HTTPS_PROXY HTTP_PROXY MACHINE NO_PROXY PARALLEL_MAKE SCREENDIR SDKMACHINE SOCKS5_PASSWD SOCKS5_USER SSH_AGENT_PID SSH_AUTH_SOCK STAMPS_DIR TCLIBC TCMODE all_proxy ftp_proxy ftps_proxy http_proxy https_proxy no_proxy ', 'USER': 'pokybuild', 'FTP_PROXY': 'http://proxy.yocto.io:5187/', 'PATH': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/scripts:/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin:/home/pokybuild/.local/bin:/home/pokybuild/bin:/usr/lib64/ccache:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin', 'LC_ALL': 'en_US.UTF-8', 'HISTCONTROL': 'ignoredups', 'HISTSIZE': '1000', 'HOSTNAME': 'fedora31-ty-1', 'ABHELPER_JSON': 'config.json /home/pokybuild/config-local.json', '_': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin/bitbake-layers', 'LANG': 'en_US.UTF-8', 'LS_COLORS': 'rs=0:di=38;5;33:ln=38;5;51:mh=00:pi=40;38;5;11:so=38;5;13:do=38;5;5:bd=48;5;232;38;5;11:cd=48;5;232;38;5;3:or=48;5;232;38;5;9:mi=01;37;41:su=48;5;196;38;5;15:sg=48;5;11;38;5;16:ca=48;5;196;38;5;226:tw=48;5;10;38;5;16:ow=48;5;10;38;5;21:st=48;5;21;38;5;15:ex=38;5;40:*.tar=38;5;9:*.tgz=38;5;9:*.arc=38;5;9:*.arj=38;5;9:*.taz=38;5;9:*.lha=38;5;9:*.lz4=38;5;9:*.lzh=38;5;9:*.lzma=38;5;9:*.tlz=38;5;9:*.txz=38;5;9:*.tzo=38;5;9:*.t7z=38;5;9:*.zip=38;5;9:*.z=38;5;9:*.dz=38;5;9:*.gz=38;5;9:*.lrz=38;5;9:*.lz=38;5;9:*.lzo=38;5;9:*.xz=38;5;9:*.zst=38;5;9:*.tzst=38;5;9:*.bz2=38;5;9:*.bz=38;5;9:*.tbz=38;5;9:*.tbz2=38;5;9:*.tz=38;5;9:*.deb=38;5;9:*.rpm=38;5;9:*.jar=38;5;9:*.war=38;5;9:*.ear=38;5;9:*.sar=38;5;9:*.rar=38;5;9:*.alz=38;5;9:*.ace=38;5;9:*.zoo=38;5;9:*.cpio=38;5;9:*.7z=38;5;9:*.rz=38;5;9:*.cab=38;5;9:*.wim=38;5;9:*.swm=38;5;9:*.dwm=38;5;9:*.esd=38;5;9:*.jpg=38;5;13:*.jpeg=38;5;13:*.mjpg=38;5;13:*.mjpeg=38;5;13:*.gif=38;5;13:*.bmp=38;5;13:*.pbm=38;5;13:*.pgm=38;5;13:*.ppm=38;5;13:*.tga=38;5;13:*.xbm=38;5;13:*.xpm=38;5;13:*.tif=38;5;13:*.tiff=38;5;13:*.png=38;5;13:*.svg=38;5;13:*.svgz=38;5;13:*.mng=38;5;13:*.pcx=38;5;13:*.mov=38;5;13:*.mpg=38;5;13:*.mpeg=38;5;13:*.m2v=38;5;13:*.mkv=38;5;13:*.webm=38;5;13:*.ogm=38;5;13:*.mp4=38;5;13:*.m4v=38;5;13:*.mp4v=38;5;13:*.vob=38;5;13:*.qt=38;5;13:*.nuv=38;5;13:*.wmv=38;5;13:*.asf=38;5;13:*.rm=38;5;13:*.rmvb=38;5;13:*.flc=38;5;13:*.avi=38;5;13:*.fli=38;5;13:*.flv=38;5;13:*.gl=38;5;13:*.dl=38;5;13:*.xcf=38;5;13:*.xwd=38;5;13:*.yuv=38;5;13:*.cgm=38;5;13:*.emf=38;5;13:*.ogv=38;5;13:*.ogx=38;5;13:*.aac=38;5;45:*.au=38;5;45:*.flac=38;5;45:*.m4a=38;5;45:*.mid=38;5;45:*.midi=38;5;45:*.mka=38;5;45:*.mp3=38;5;45:*.mpc=38;5;45:*.ogg=38;5;45:*.ra=38;5;45:*.wav=38;5;45:*.oga=38;5;45:*.opus=38;5;45:*.spx=38;5;45:*.xspf=38;5;45:', 'OEQA_DEBUGGING_SAVED_OUTPUT': '/srv/autobuilder/autobuilder.yoctoproject.org/pub/repro-fail/', 'TERM': 'xterm-256color', 'SCRIPTSDIR': '/home/pokybuild/yocto-worker/oe-selftest-fedora/yocto-autobuilder-helper/scripts', 'LESSOPEN': '||/usr/bin/lesspipe.sh %s', 'DISPLAY': ':1', 'SHLVL': '2', 'BUILDDIR': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build/build-st-3670103', 'MAIL': '/var/spool/mail/pokybuild', 'OLDPWD': '/home/pokybuild/yocto-worker/oe-selftest-fedora/build'}, ['/home/pokybuild/yocto-worker/oe-selftest-fedora/build/bitbake/bin/bitbake-layers', 'remove-layer', '*/workspace']]
741306 16:23:27.145524 Command Completed
741306 16:23:27.147293 Running command ['parseConfiguration']
741306 16:23:27.150737 Command Completed
741306 16:23:27.151143 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBMULTICONFIG',), {}]
741306 16:23:27.151752 Command Completed
741306 16:23:27.152027 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBPATH',), {}]
741306 16:23:27.166126 Command Completed
741306 16:23:27.167288 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBLAYERS',), {}]
741306 16:23:27.167686 Command Completed
741306 16:23:27.168209 Running command ['dataStoreConnectorVarHistCmd', 0, 'get_variable_items_files', ('BBFILE_COLLECTIONS',), {}]
741306 16:23:27.168629 Command Completed
741306 16:23:27.174122 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBLAYERS',), {}]
741306 16:23:27.174681 Command Completed
741306 16:23:27.175209 Running command ['dataStoreConnectorVarHistCmd', 0, 'get_variable_items_files', ('BBFILE_COLLECTIONS',), {}]
741306 16:23:27.175596 Command Completed
741306 16:23:27.178116 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBLAYERS',), {}]
741306 16:23:27.178561 Command Completed
741306 16:23:27.179106 Running command ['dataStoreConnectorVarHistCmd', 0, 'get_variable_items_files', ('BBFILE_COLLECTIONS',), {}]
741306 16:23:27.179478 Command Completed
741306 16:23:27.181009 Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBLAYERS',), {}]
741306 16:23:27.181356 Command Completed
741306 16:23:27.181831 Running command ['dataStoreConnectorVarHistCmd', 0, 'get_variable_items_files', ('BBFILE_COLLECTIONS',), {}]
741306 16:23:27.182228 Command Completed
741306 16:23:27.185289 Running command ['clientComplete']
741306 16:23:27.185479 Command Completed
741306 16:23:27.186830 Processing Client
741306 16:23:27.186927 Disconnecting Client
741306 16:23:27.187233 No timeout, exiting.