AWS Thinkbox Discussion Forums

slave unable to cancel task

2016-05-19 08:15:51:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:15:51:      current status = Rendering, new status = Rendering
2016-05-19 08:15:51:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:15:51:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:15:51:  Scheduler Thread - Cancelling task...
2016-05-19 08:15:51:  0: Executing plugin command of type 'Cancel Task'
2016-05-19 08:15:51:  0: Done executing plugin command of type 'Cancel Task'
2016-05-19 08:18:54:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:18:54:      current status = Rendering, new status = Rendering
2016-05-19 08:18:54:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:18:54:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:18:54:  Scheduler Thread - Cancelling task...
2016-05-19 08:18:54:  0: Executing plugin command of type 'Cancel Task'
2016-05-19 08:18:54:  0: Done executing plugin command of type 'Cancel Task'
2016-05-19 08:21:58:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:21:58:      current status = Rendering, new status = Rendering
2016-05-19 08:21:58:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:21:58:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:21:58:  Scheduler Thread - Cancelling task...
2016-05-19 08:21:58:  0: Executing plugin command of type 'Cancel Task'
2016-05-19 08:21:58:  0: Done executing plugin command of type 'Cancel Task'
2016-05-19 08:25:01:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:25:01:      current status = Rendering, new status = Rendering
2016-05-19 08:25:01:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:25:01:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:25:01:  Scheduler Thread - Cancelling task...
2016-05-19 08:25:01:  0: Executing plugin command of type 'Cancel Task'
2016-05-19 08:25:01:  0: Done executing plugin command of type 'Cancel Task'
2016-05-19 08:28:02:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:28:02:      current status = Rendering, new status = Rendering
2016-05-19 08:28:02:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:28:02:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:28:02:  Scheduler Thread - Cancelling task...
2016-05-19 08:28:02:  0: Executing plugin command of type 'Cancel Task'
2016-05-19 08:28:02:  0: Done executing plugin command of type 'Cancel Task'
2016-05-19 08:31:06:  Scheduler Thread - Task "15_1020-1020" could not be found because task has been modified:
2016-05-19 08:31:06:      current status = Rendering, new status = Rendering
2016-05-19 08:31:06:      current slave = LAPRO1873, new slave = LAPRO3234
2016-05-19 08:31:06:      current frames = 1020-1020, new frames = 1020-1020
2016-05-19 08:31:06:  Scheduler Thread - Cancelling task...

Last lines of the previous log before that is pretty standard, its running our jobpreload python script, IDs the config batch it should run, but never seems to finish properly:

2016-05-18 22:02:04:  Scanline: OnSlaveStartingJob sSlaveName LAPRO1873
2016-05-18 22:02:04:  Scanline: OnSlaveStartingJob sJobID 573d1191e461d25084febcd4
2016-05-18 22:02:04:  Scanline: RemoveJobFolderContents event called LAPRO1873
2016-05-18 22:02:04:  Scanline: cleaning sJobsDataFolder: C:\Users\scanlinevfx\AppData\Local\Thinkbox\Deadline8\slave\LAPRO1873\jobsData
2016-05-18 22:02:04:  Scheduler Thread - Synchronization time for job files: 46.804 ms
2016-05-18 22:02:04:  Syncronizing Plugin 3dsmax from \\inferno2\deadline\repository8\plugins\3dsmax
2016-05-18 22:02:05:  Syncronization complete. Took: 0 seconds
2016-05-18 22:02:05:  0: Got task!
2016-05-18 22:02:05:  0: Plugin will be reloaded because a new job has been loaded, or one of the job files or plugin files has been modified
2016-05-18 22:02:07:  0: Loaded plugin 3dsmax (\\inferno2\deadline\repository8\plugins\3dsmax)
2016-05-18 22:02:07:  0: Executing plugin command of type 'Initialize Plugin'
2016-05-18 22:02:09:  0: INFO: Executing plugin script 'S:\deadlinedata\lapro1873\plugins\573d1191e461d25084febcd4\3dsmax.py'
2016-05-18 22:02:09:  0: INFO: The job's environment will be merged with the current environment before rendering
2016-05-18 22:02:09:  0: Done executing plugin command of type 'Initialize Plugin'
2016-05-18 22:02:10:  0: Start Job timeout is disabled.
2016-05-18 22:02:10:  0: Task timeout is 21600 seconds (Regular Task Timeout)
2016-05-18 22:02:10:  0: Loaded job: [KA] DRK_079_1785_v0011_rui_UpdatedLayout_images_render3d_Light-WetPass_0 (573d1191e461d25084febcd4)
2016-05-18 22:02:10:  0: Executing plugin command of type 'Start Job'
2016-05-18 22:02:10:  0: INFO: Executing job preload script 'S:\deadlinedata\lapro1873\plugins\573d1191e461d25084febcd4\JobPreLoad.py'
2016-05-18 22:02:10:  0: PYTHON: Attempting to import ScanlineSite...
2016-05-18 22:02:10:  0: PYTHON: Setting variables...
2016-05-18 22:02:10:  0: PYTHON: ScanlineSite.sLibraryPrefix //s2.scanlinevfxla.com/exchange/software/managed/
2016-05-18 22:02:10:  0: PYTHON: OVERRIDE_CONFIG_SERVER = \\s2.scanlinevfxla.com\exchange\software\
2016-05-18 22:02:10:  0: PYTHON: Getting version...
2016-05-18 22:02:10:  0: PYTHON: Attempting to import scl.pipeline.Paths...
2016-05-18 22:02:10:  0: PYTHON: Success!
2016-05-18 22:02:10:  0: INFO: JobPreLoad.__main__ version: 1.59
2016-05-18 22:02:10:  0: INFO: RUN SCENEJANITOR
2016-05-18 22:02:10:  0: INFO: ---Starting thread for command: \\s2.scanlinevfxla.com\exchange\software\managed\pythonScripts\drive_janitor\clean_render_node_drives.bat
2016-05-18 22:02:16:  0: INFO: ---Thread std output: 
2016-05-18 22:02:16:  0: C:\Program Files\Thinkbox\Deadline8\bin>"C:\python26_64\python.exe" "\\S2\exchange\software\managed\pythonScripts\drive_janitor\drive_janitor.py" "S:/A/inferno2/" 90 
2016-05-18 22:02:16:  0: Scanline Sitecustomize v0.40
2016-05-18 22:02:16:  0: Turned off pyc generation
2016-05-18 22:02:16:  0: Adding initial site paths #0.: //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/sitecustomize
2016-05-18 22:02:16:  0: Adding initial site paths #1.: //inferno2.scanlinevfxla.com/exchange/software/managed/pythonScripts/sitecustomize
2016-05-18 22:02:16:  0: Scanline Site Loader v0.49
2016-05-18 22:02:16:  0: resolveConfigName: C:\python26_64\python.exe
2016-05-18 22:02:16:  0: Loading config: default
2016-05-18 22:02:16:  0: Config path = \\s2.scanlinevfxla.com\exchange\software\managed\pythonScripts\sitecustomize\ScanlineSite\configs\default.py 
2016-05-18 22:02:16:  0: Clearing QT environment variables
2016-05-18 22:02:16:  0: Resetting QT environment variables: \\s2.scanlinevfxla.com\exchange\software\managed\Libraries\Qt\4.5.0_x64
2016-05-18 22:02:16:  0: Adding site path //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/site-packages
2016-05-18 22:02:16:  0: Adding site path //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/site-packages_2.6_MSVC1500_64
2016-05-18 22:02:16:  0: Adding site path //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/site-packages_configured/sip/windows_amd64_msc8_python26__4_8
2016-05-18 22:02:16:  0: Adding site path //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/site-packages_configured/PyQt4/windows_amd64_msc8_python26__pyqt4_5_qt4_5_0
2016-05-18 22:02:16:  0: Adding site path //s2.scanlinevfxla.com/exchange/software/managed/pythonScripts/site-packages_configured/scl/windows_amd64_msc9_python26__qt4_7_1_internal
2016-05-18 22:02:16:  0: Scanline Site Initialized
2016-05-18 22:02:16:  0: ======================================================================================
2016-05-18 22:02:16:  0: scLog DriveJanitor initializing in farm mode (printing to stdout)
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+0ms)     :(DriveJanitor): debug : New log file created using scLog v0.11
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+0ms)     :(DriveJanitor): debug : clearInactiveLogs
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+78ms)    :(DriveJanitor): debug : Farm mode: True stdout: <open file '<stdout>', mode 'w' at 0x0000000001F0C140>
2016-05-18 22:02:16:  0: Drive Janitor v3.00 starting...
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+0ms)     :(DriveJanitor): debug : Drive Janitor v3.00 starting...
2016-05-18 22:02:16:  0: Total disk space : 1994373mb ( 1994.373gb )
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+0ms)     :(DriveJanitor): debug : Total disk space : 1994373mb ( 1994.373gb )
2016-05-18 22:02:16:  0: Target disk usage : 1695217mb ( 1695.217gb ) ( 85% )
2016-05-18 22:02:16:  0: Wed May 18 22:02:11 2016 (+0ms)     :(DriveJanitor): debug : Target disk usage : 1695217mb ( 1695.217gb ) ( 85% )
2016-05-18 22:02:16:  0: Current disk usage : 1694710mb ( 1694.71gb ) ( 84% )
2016-05-18 22:02:16:  0: Wed May 18 22:02:16 2016 (+4585ms)  :(DriveJanitor): debug : Current disk usage : 1694710mb ( 1694.71gb ) ( 84% )
2016-05-18 22:02:16:  0: Current disk usage is on target, skipping
2016-05-18 22:02:16:  0: Wed May 18 22:02:16 2016 (+0ms)     :(DriveJanitor): debug : Current disk usage is on target, skipping
2016-05-18 22:02:16:  0: Drive Janitor v3.00 completed work
2016-05-18 22:02:16:  0: Wed May 18 22:02:16 2016 (+46ms)    :(DriveJanitor): debug : Drive Janitor v3.00 completed work
2016-05-18 22:02:16:  0: INFO: ---Thread err output: 
2016-05-18 22:02:16:  0: INFO: ---Thread finished
2016-05-18 22:02:16:  0: INFO: ---Process exit code: 0
2016-05-18 22:02:16:  0: INFO: Drive janitor done
2016-05-18 22:02:16:  0: INFO: wrangling env variables
2016-05-18 22:02:16:  0: INFO: JobPreLoad.unsetEnvironmentVariables
2016-05-18 22:02:16:  0: INFO: Delete: SCL_CONFIG_FARM_MODE
2016-05-18 22:02:16:  0: INFO: JobPreLoad Setting Job Environment Variables
2016-05-18 22:02:16:  0: INFO: 	JobPreLoad Setting: SCL_CONFIG_FARM_MODE = 1
2016-05-18 22:02:16:  0: INFO: 	JobPreLoad Setting: FLOWLINE2_PLUGIN_INI_MAX = c:\flowline2.5\ini\flplugs_max.ini
2016-05-18 22:02:16:  0: INFO: 	JobPreLoad Setting: FLOWLINEVERSION = 6516
2016-05-18 22:02:16:  0: INFO: 	JobPreLoad Setting: FLOWLINE2_CFG_INI = C:\Flowline2.5\ini\flconfig.ini
2016-05-18 22:02:16:  0: INFO: Done.
2016-05-18 22:02:16:  0: INFO: Checking slave affinity settings for: LAPRO1873
2016-05-18 22:02:16:  0: INFO: Setting VRAY_NUM_THREADS to: 19
2016-05-18 22:02:16:  0: INFO: Job is using flowline
2016-05-18 22:02:16:  0: INFO: Job aux path: \\inferno2\deadline\repository8\jobs\573d1191e461d25084febcd4
2016-05-18 22:02:16:  0: INFO: NUMBER_OF_PROCESSORS environment variable is set to: 20
2016-05-18 22:02:16:  0: INFO: FLOWLINE2_BASECFG_INI is set to: \\S2\exchange\software\managed\flowline\FLOWLINE2_BASECFG_INI_20threads.ini
2016-05-18 22:02:16:  0: INFO: Farm mode: using farm config
2016-05-18 22:02:16:  0: PYTHON: Overriding config path to: \\s2.scanlinevfxla.com\exchange\software\
2016-05-18 22:02:16:  0: INFO: Running max farmHealth cleanup
2016-05-18 22:02:16:  0: PYTHON: scl.max.farmHealth.doCleanup called for max2015
2016-05-18 22:02:16:  0: PYTHON: scl.max.farmHealth.deleteTempScripts called for max2015
2016-05-18 22:02:16:  0: PYTHON: Could not list contents of /home/scanlinevfx/AppData/Local/Autodesk/3dsMax/2015 - 64bit/ENU/usermacros
2016-05-18 22:02:16:  0: INFO: Scanline 3ds Max config file: \\s2.scanlinevfxla.com\exchange\software\managed\SoftwareConfiguration\Max2015\ConfigurationSettings\KA_Prestart_Max2015_64Bit_Farm.bat

Again, trying to shut down the slave is unsuccessful, it just freezes it (seems like it cant kill its python sandbox processes). Requires a manual task manager process kill to shut it down.

Thanks for the report, I suspect this is likely an issue with us being a bit too ‘polite’ with our task cancellation requests, especially during the JobPreLoad phase.

Should hopefully be easy enough to address.

Privacy | Site terms | Cookie preferences