---------------------------------------- DSS startup: jek version:8.0.2 DSS home: /appl/dataiku/dss_data OS: Linux 3.10.0-1127.19.1.el7.x86_64 amd64 - Java: Oracle Corporation 1.8.0_262 [2020/10/21-10:24:54.074] [qtp1906029492-20] [INFO] [dku.jobs] - Connects using Shared secret [2020/10/21-10:24:54.074] [qtp1906029492-20] [DEBUG] [dku.jobs] - Received command : /pintercom/start_session [2020/10/21-10:24:54.085] [qtp1906029492-20] [INFO] [dku.jobs] - Start Session: {"jobProjectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","jobTicketSecret":"####","initiatorAuthContext":{"userGroupLevelPermissions":{"admin":true,"mayManageUDM":true,"mayCreateProjects":true,"mayCreateProjectsFromMacros":true,"mayCreateProjectsFromTemplates":true,"mayCreateProjectsFromDataikuApps":true,"mayWriteUnsafeCode":true,"mayWriteSafeCode":true,"mayCreateAuthenticatedConnections":true,"mayCreateCodeEnvs":true,"mayCreateClusters":true,"mayDevelopPlugins":true,"mayEditLibFolders":true,"mayManageCodeEnvs":true,"mayManageClusters":true,"mayViewIndexedHiveConnections":true,"mayCreatePublishedAPIServices":true,"mayWriteInRootProjectFolder":true,"mayCreateActiveWebContent":true,"canObtainAPITicketFromCookiesForGroupsRegex":""},"via":[],"authSource":"USER_FROM_UI","realUserLogin":"#######","userGroups":["#######","#######","#######"],"userProfile":"PLATFORM_ADMIN"}} [2020/10/21-10:24:54.093] [qtp1906029492-20] [INFO] [dip.tickets.fixed] - Creating service for single API ticket in auth context: ####### [2020/10/21-10:24:54.110] [qtp1906029492-20] [DEBUG] [dku.jobs] - Command /pintercom/start_session processed in 37ms [2020/10/21-10:24:54.126] [qtp1906029492-21] [INFO] [dku.jobs] - Connects using Shared secret [2020/10/21-10:24:54.127] [qtp1906029492-21] [DEBUG] [dku.jobs] - Received command : /pintercom/resolve_job [2020/10/21-10:24:54.127] [qtp1906029492-21] [INFO] [dku.job.slave] - Starting to resolve job [2020/10/21-10:24:54.244] [qtp1906029492-21] [INFO] [dku.job.slave] - { "type": "RECURSIVE_FORCED_BUILD", "projectKey": "#######", "id": "Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407", "name": "Build iris_plots, iris_by_variety", "initiator": "#######", "initiationTimestamp": 1603268689407, "mailNotification": false, "outputs": [ { "type": "MANAGED_FOLDER", "targetDatasetProjectKey": "#######", "targetDataset": "#######" }, { "type": "DATASET", "targetDatasetProjectKey": "#######", "targetDataset": "iris_by_variety" } ], "refreshHiveMetastore": true } [2020/10/21-10:24:54.244] [qtp1906029492-21] [INFO] [dku.job.slave] - Loading recipes [2020/10/21-10:24:54.250] [qtp1906029492-21] [DEBUG] [dku.flow.recipes] - Building global graph [2020/10/21-10:24:54.321] [qtp1906029492-21] [DEBUG] [dku.flow.recipes] - Done getting global graph t=71ms [2020/10/21-10:24:54.342] [qtp1906029492-21] [INFO] [dku.job.slave] - Recipes loaded, computing job details [2020/10/21-10:24:54.362] [qtp1906029492-21] [INFO] [dku.flow.compute] - Job output type: MANAGED_FOLDER [2020/10/21-10:24:54.372] [qtp1906029492-21] [INFO] [dku.flow.compute] - computing job from target #######.####### partition NP [2020/10/21-10:24:54.373] [qtp1906029492-21] [INFO] [dku.flow.compute] - Refreshing #######.#######/NP with recipe compute_####### 4.907: [GC (Allocation Failure) [PSYoungGen: 126333K->12275K(134144K)] 136866K->23584K(177152K), 0.0341941 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] [2020/10/21-10:24:54.426] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_#######_ - Compute output partitions for subgraph, with target : #######.####### and partition: NP [2020/10/21-10:24:54.426] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_#######_ - Target #######.####### is not partitioned [2020/10/21-10:24:54.426] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_#######_ - Add output partition for #######.####### : NP [2020/10/21-10:24:54.426] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_#######_ - computed output partitions: {#######.#######=} [2020/10/21-10:24:54.439] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_#######_ - 0 dependency for #######.iris_copy [2020/10/21-10:24:54.440] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_#######_ - source #######.iris_copy is not partitioned, including the global partition [2020/10/21-10:24:54.441] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_#######_ - computed input partitions : {#######.iris_copy=[]} [2020/10/21-10:24:54.442] [qtp1906029492-21] [INFO] [dku.flow.compute] - Refreshing #######.iris_copy/NP with recipe compute_iris_copy [2020/10/21-10:24:54.443] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Compute output partitions for subgraph, with target : #######.iris_copy and partition: NP [2020/10/21-10:24:54.443] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Target #######.iris_copy is not partitioned [2020/10/21-10:24:54.443] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Add output partition for #######.iris_copy : NP [2020/10/21-10:24:54.443] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_copy_ - computed output partitions: {#######.iris_copy=} [2020/10/21-10:24:54.444] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_copy_ - 0 dependency for #######.iris [2020/10/21-10:24:54.444] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_copy_ - source #######.iris is not partitioned, including the global partition [2020/10/21-10:24:54.444] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_copy_ - computed input partitions : {#######.iris=[]} [2020/10/21-10:24:54.444] [qtp1906029492-21] [INFO] [dku.flow.compute] - End of tree reached [2020/10/21-10:24:54.445] [qtp1906029492-21] [INFO] [dku.flow.compute] - Job output type: DATASET [2020/10/21-10:24:54.449] [qtp1906029492-21] [INFO] [dku.flow.compute] - computing job from target #######.iris_by_variety partition NP [2020/10/21-10:24:54.451] [qtp1906029492-21] [INFO] [dku.flow.compute] - Refreshing #######.iris_by_variety/NP with recipe compute_iris_by_variety [2020/10/21-10:24:54.451] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_by_variety_ - Compute output partitions for subgraph, with target : #######.iris_by_variety and partition: NP [2020/10/21-10:24:54.451] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_by_variety_ - Target #######.iris_by_variety is not partitioned [2020/10/21-10:24:54.452] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_by_variety_ - Add output partition for #######.iris_by_variety : NP [2020/10/21-10:24:54.452] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_by_variety_ - computed output partitions: {#######.iris_by_variety=} [2020/10/21-10:24:54.452] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_by_variety_ - 0 dependency for #######.iris_copy [2020/10/21-10:24:54.453] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_by_variety_ - source #######.iris_copy is not partitioned, including the global partition [2020/10/21-10:24:54.453] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_by_variety_ - computed input partitions : {#######.iris_copy=[]} [2020/10/21-10:24:54.453] [qtp1906029492-21] [INFO] [dku.flow.compute] - Refreshing #######.iris_copy/NP with recipe compute_iris_copy [2020/10/21-10:24:54.453] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Compute output partitions for subgraph, with target : #######.iris_copy and partition: NP [2020/10/21-10:24:54.454] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Target #######.iris_copy is not partitioned [2020/10/21-10:24:54.454] [qtp1906029492-21] [INFO] [dku.flow.compute.op] activity compute_iris_copy_ - Add output partition for #######.iris_copy : NP [2020/10/21-10:24:54.454] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_copy_ - computed output partitions: {#######.iris_copy=} [2020/10/21-10:24:54.454] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_copy_ - 0 dependency for #######.iris [2020/10/21-10:24:54.455] [qtp1906029492-21] [INFO] [dku.flow.compute.ip] activity compute_iris_copy_ - source #######.iris is not partitioned, including the global partition [2020/10/21-10:24:54.455] [qtp1906029492-21] [INFO] [dku.flow.compute] activity compute_iris_copy_ - computed input partitions : {#######.iris=[]} [2020/10/21-10:24:54.455] [qtp1906029492-21] [INFO] [dku.flow.compute] - This activity is an alias! [2020/10/21-10:24:54.458] [qtp1906029492-21] [INFO] [dku.flow.compute] - Before prune, job looks like: JOB ACTIVITY ROOT DEPS ACTIVITY compute_#######_NP SGID: compute_#######_NP SRC: #######.iris_copy (partitions: NP) DST: #######.####### (partition: NP) DEPS ACTIVITY compute_iris_copy_NP SGID: compute_iris_copy_NP SRC: #######.iris (partitions: NP) DST: #######.iris_copy (partition: NP) ACTIVITY compute_iris_by_variety_NP SGID: compute_iris_by_variety_NP SRC: #######.iris_copy (partitions: NP) DST: #######.iris_by_variety (partition: NP) DEPS NON-PRINTED DEP (already printed): compute_iris_copy_NP [2020/10/21-10:24:54.459] [qtp1906029492-21] [INFO] [dku.flow.compute] - After cleanup of implicit recipes, job looks like: JOB ACTIVITY ROOT DEPS ACTIVITY compute_#######_NP SGID: compute_#######_NP SRC: #######.iris_copy (partitions: NP) DST: #######.####### (partition: NP) DEPS ACTIVITY compute_iris_copy_NP SGID: compute_iris_copy_NP SRC: #######.iris (partitions: NP) DST: #######.iris_copy (partition: NP) ACTIVITY compute_iris_by_variety_NP SGID: compute_iris_by_variety_NP SRC: #######.iris_copy (partitions: NP) DST: #######.iris_by_variety (partition: NP) DEPS NON-PRINTED DEP (already printed): compute_iris_copy_NP [2020/10/21-10:24:54.463] [qtp1906029492-21] [INFO] [dku.flow.compute] - Job project: ####### [2020/10/21-10:24:54.474] [qtp1906029492-21] [INFO] [dku.flow.compute] - Doing job pruning according to settings [2020/10/21-10:24:54.479] [qtp1906029492-21] [INFO] [dku.flow.compute] - RECURSIVE_FORCED_BUILD: pruning non-required activities [2020/10/21-10:24:54.485] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * ROOT: Checking ROOT [2020/10/21-10:24:54.486] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_#######_NP: Checking compute_#######_NP [2020/10/21-10:24:54.486] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Checking compute_iris_copy_NP [2020/10/21-10:24:54.487] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Item has no dependencies, checking its sources [2020/10/21-10:24:54.488] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Checking readiness of #######.iris [2020/10/21-10:24:54.497] [qtp1906029492-21] [DEBUG] [dku.dataset.hash] - Readiness cache miss for dataset__#######__#######.iris__NP [2020/10/21-10:24:54.522] [qtp1906029492-21] [INFO] [dku.datasets.file] - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:24:54.524] [qtp1906029492-21] [INFO] [dku.datasets.ftplike] - Enumerating Filesystem dataset prefix= [2020/10/21-10:24:54.530] [qtp1906029492-21] [DEBUG] [dku.fs.local] - Enumerating local filesystem prefix=/ [2020/10/21-10:24:54.531] [qtp1906029492-21] [DEBUG] [dku.fs.local] - Enumeration done nb_paths=1 size=3975 [2020/10/21-10:24:54.536] [qtp1906029492-21] [INFO] [dku.dataset.hash] - Caching readiness for dataset__#######__#######.iris__NP s=READY h=9jfKmH4Adb4rIwT35boHtg [2020/10/21-10:24:54.537] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Readiness of #######.iris: READY [2020/10/21-10:24:54.537] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_by_variety_NP: Checking compute_iris_by_variety_NP [2020/10/21-10:24:54.539] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Checking compute_iris_copy_NP [2020/10/21-10:24:54.540] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Item has no dependencies, checking its sources [2020/10/21-10:24:54.540] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Checking readiness of #######.iris [2020/10/21-10:24:54.543] [qtp1906029492-21] [DEBUG] [dku.dataset.hash] - Readiness cache hit for dataset__#######__#######.iris__NP: s=READY h=9jfKmH4Adb4rIwT35boHtg [2020/10/21-10:24:54.543] [qtp1906029492-21] [INFO] [dku.flow.compute.prune] - * compute_iris_copy_NP: Readiness of #######.iris: READY [2020/10/21-10:24:54.547] [qtp1906029492-21] [INFO] [dku.flow.compute] - After prune, job looks like that [2020/10/21-10:24:54.548] [qtp1906029492-21] [INFO] [dku.flow.compute] - JOB ACTIVITY ROOT DEPS ACTIVITY compute_#######_NP SGID: compute_#######_NP SRC: #######.iris_copy (partitions: NP) DST: #######.####### (partition: NP) DEPS ACTIVITY compute_iris_copy_NP SGID: compute_iris_copy_NP SRC: #######.iris (partitions: NP) DST: #######.iris_copy (partition: NP) ACTIVITY compute_iris_by_variety_NP SGID: compute_iris_by_variety_NP SRC: #######.iris_copy (partitions: NP) DST: #######.iris_by_variety (partition: NP) DEPS NON-PRINTED DEP (already printed): compute_iris_copy_NP [2020/10/21-10:24:54.548] [qtp1906029492-21] [INFO] [dku.flow.compute] - Done building final job graph [2020/10/21-10:24:54.548] [qtp1906029492-21] [INFO] [dku.job.slave] - Done computing job data, dumping graph [2020/10/21-10:24:54.549] [qtp1906029492-21] [INFO] [dku.job.slave] - JOB ACTIVITY ROOT DEPS ACTIVITY compute_#######_NP SGID: compute_#######_NP SRC: #######.iris_copy (partitions: NP) DST: #######.####### (partition: NP) DEPS ACTIVITY compute_iris_copy_NP SGID: compute_iris_copy_NP SRC: #######.iris (partitions: NP) DST: #######.iris_copy (partition: NP) ACTIVITY compute_iris_by_variety_NP SGID: compute_iris_by_variety_NP SRC: #######.iris_copy (partitions: NP) DST: #######.iris_by_variety (partition: NP) DEPS NON-PRINTED DEP (already printed): compute_iris_copy_NP [2020/10/21-10:24:54.551] [qtp1906029492-21] [INFO] [dku.job.slave] - Job has the following sources: [{"projectKey":"#######","type":"DATASET","id":"iris_copy"},{"projectKey":"#######","type":"DATASET","id":"iris"}] [2020/10/21-10:24:54.551] [qtp1906029492-21] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_DATA::#######.iris_copy [2020/10/21-10:24:54.574] [qtp1906029492-21] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_DATA::#######.iris [2020/10/21-10:24:54.602] [qtp1906029492-21] [DEBUG] [dku.jobs] - Command /pintercom/resolve_job processed in 476ms [2020/10/21-10:25:32.681] [qtp1906029492-22] [INFO] [dku.jobs] - Connects using Shared secret [2020/10/21-10:25:32.681] [qtp1906029492-22] [DEBUG] [dku.jobs] - Received command : /pintercom/run_fully [2020/10/21-10:25:32.696] [qtp1906029492-22] [INFO] [dku.job.slave] - Job run started in kernel with pid 29406 [2020/10/21-10:25:32.697] [qtp1906029492-22] [INFO] [dku.flow.jobrunner] - Creating 5 activity runner thread(s). [2020/10/21-10:25:32.698] [qtp1906029492-22] [INFO] [dku.flow.jobrunner] - Starting activity executor threads [2020/10/21-10:25:32.700] [qtp1906029492-22] [INFO] [dku.flow.jobrunner] - Waiting for activity executor threads [2020/10/21-10:25:32.704] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] - About to run compute_iris_copy_NP [2020/10/21-10:25:32.715] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] running compute_iris_copy_NP - Allocated a slot for this activity! [2020/10/21-10:25:32.717] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] running compute_iris_copy_NP - Run activity [2020/10/21-10:25:32.727] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Executing default pre-activity lifecycle hook [2020/10/21-10:25:32.737] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Checking if sources are ready [2020/10/21-10:25:32.741] [ActivityExecutor-28] [DEBUG] [dku.dataset.hash] running compute_iris_copy_NP - Readiness cache miss for dataset__#######__#######.iris__NP [2020/10/21-10:25:32.747] [ActivityExecutor-28] [INFO] [dku.datasets.file] running compute_iris_copy_NP - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:32.748] [ActivityExecutor-28] [INFO] [dku.datasets.ftplike] running compute_iris_copy_NP - Enumerating Filesystem dataset prefix= [2020/10/21-10:25:32.749] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumerating local filesystem prefix=/ [2020/10/21-10:25:32.749] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumeration done nb_paths=1 size=3975 [2020/10/21-10:25:32.750] [ActivityExecutor-28] [INFO] [dku.dataset.hash] running compute_iris_copy_NP - Caching readiness for dataset__#######__#######.iris__NP s=READY h=9jfKmH4Adb4rIwT35boHtg [2020/10/21-10:25:32.750] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Checked source readiness #######.iris -> true [2020/10/21-10:25:32.760] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Computing hashes to propagate BEFORE activity [2020/10/21-10:25:32.764] [ActivityExecutor-28] [DEBUG] [dku.dataset.hash] running compute_iris_copy_NP - Readiness cache miss for dataset__#######__#######.iris__NP [2020/10/21-10:25:32.775] [ActivityExecutor-28] [INFO] [dku.datasets.file] running compute_iris_copy_NP - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:32.776] [ActivityExecutor-28] [INFO] [dku.datasets.ftplike] running compute_iris_copy_NP - Enumerating Filesystem dataset prefix= [2020/10/21-10:25:32.776] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumerating local filesystem prefix=/ [2020/10/21-10:25:32.777] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumeration done nb_paths=1 size=3975 [2020/10/21-10:25:32.777] [ActivityExecutor-28] [INFO] [dku.dataset.hash] running compute_iris_copy_NP - Caching readiness for dataset__#######__#######.iris__NP s=READY h=9jfKmH4Adb4rIwT35boHtg [2020/10/21-10:25:32.778] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Recorded 1 hashes before activity run [2020/10/21-10:25:32.778] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Building recipe runner of type [2020/10/21-10:25:32.792] [ActivityExecutor-28] [DEBUG] [dku.job.activity] running compute_iris_copy_NP - Filling source sizes [2020/10/21-10:25:32.797] [ActivityExecutor-28] [INFO] [dku.datasets.file] running compute_iris_copy_NP - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:32.797] [ActivityExecutor-28] [INFO] [dku.datasets.ftplike] running compute_iris_copy_NP - Enumerating Filesystem dataset prefix= [2020/10/21-10:25:32.798] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumerating local filesystem prefix=/ [2020/10/21-10:25:32.799] [ActivityExecutor-28] [DEBUG] [dku.fs.local] running compute_iris_copy_NP - Enumeration done nb_paths=1 size=3975 [2020/10/21-10:25:32.799] [ActivityExecutor-28] [DEBUG] [dku.job.activity] running compute_iris_copy_NP - Done filling source sizes [2020/10/21-10:25:32.800] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Recipe runner built, will use 1 thread(s) [2020/10/21-10:25:32.800] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Starting execution thread: com.dataiku.dip.recipes.code.python.PythonRecipeRunner@462f0311 [2020/10/21-10:25:32.818] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_iris_copy_NP - Execution threads started, waiting for activity end [2020/10/21-10:25:32.822] [FRT-33-FlowRunnable] [INFO] [dku.flow.activity] act.compute_iris_copy_NP - Run thread for activity compute_iris_copy_NP starting [2020/10/21-10:25:32.824] [FRT-33-FlowRunnable] [INFO] [dku.flow.python] act.compute_iris_copy_NP - Starting execution of user's Python code [2020/10/21-10:25:32.831] [FRT-33-FlowRunnable] [INFO] [dku.venv.selector] act.compute_iris_copy_NP - Select code env lang=PYTHON projectSelection={"mode":"INHERIT","preventOverride":false} globalDefault=null [2020/10/21-10:25:32.833] [FRT-33-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_iris_copy_NP - Dumping Python script to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/script.py [2020/10/21-10:25:32.839] [FRT-33-FlowRunnable] [INFO] [dku.datasets.file] act.compute_iris_copy_NP - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:32.841] [FRT-33-FlowRunnable] [INFO] [dku.datasets.file] act.compute_iris_copy_NP - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:32.855] [FRT-33-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_iris_copy_NP - EXTERNAL LIBS FROM ####### is {"gitReferences":{},"pythonPath":["python"],"rsrcPath":["R"],"importLibrariesFromProjects":[]} [2020/10/21-10:25:32.856] [FRT-33-FlowRunnable] [DEBUG] [dku.code.projectLibs] act.compute_iris_copy_NP - Impersonation enabled, copying project ####### lib chunk /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/python to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/project-python-libs/#######/python [2020/10/21-10:25:32.857] [FRT-33-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_iris_copy_NP - chunkFolder is /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/R [2020/10/21-10:25:32.857] [FRT-33-FlowRunnable] [DEBUG] [dku.code.projectLibs] act.compute_iris_copy_NP - Impersonation enabled, copying project lib chunk /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/R to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/project-r-src/R [2020/10/21-10:25:32.859] [FRT-33-FlowRunnable] [INFO] [xxx] act.compute_iris_copy_NP - RSRC PATH: ["/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/project-r-src/R"] [2020/10/21-10:25:32.863] [FRT-33-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_iris_copy_NP - Writing dku-exec-env for local execution in /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/remote-run-env-def.json [2020/10/21-10:25:32.869] [FRT-33-FlowRunnable] [INFO] [dku.code.envs.resolution] act.compute_iris_copy_NP - Executing Python activity in env: Py36Env [2020/10/21-10:25:32.895] [FRT-33-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_iris_copy_NP - Execute activity command: ["/appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python","-u","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/python-exec-wrapper.py","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/script.py"] [2020/10/21-10:25:32.896] [FRT-33-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_iris_copy_NP - Run command insecurely, from user dataiku [2020/10/21-10:25:32.904] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Setting exclusive access on /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### [2020/10/21-10:25:32.905] [FRT-33-FlowRunnable] [DEBUG] [dku.security.fsacl] act.compute_iris_copy_NP - exec chown: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls chown --path /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### --owner ####### [2020/10/21-10:25:33.893] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:33,892 29748 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:33.895] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:33,894 29748 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:33.895] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:33,894 29748 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:34.095] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:34,094 29748 INFO Allowed group ids: [50003] [2020/10/21-10:25:34.277] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:34,277 29748 INFO User ####### belongs to groups: [503869135, 50003] [2020/10/21-10:25:34.291] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:34,290 29748 INFO User ####### belongs to group 50003 (dataiku_python_runner) -> allowed [2020/10/21-10:25:34.292] [null-err-35] [INFO] [dku.utils] - 2020-10-21 10:25:34,290 29748 INFO Executing chown -Rh: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### -> ####### [2020/10/21-10:25:34.310] [Thread-22] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:34.317] [FRT-33-FlowRunnable] [DEBUG] [dku.security.fsacl] act.compute_iris_copy_NP - exec setfacl: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls setfacl --path /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### --perm u::rwx --perm g::--- --perm o:--- --perm d:u:dataiku:rwx --perm u:dataiku:rwx --recursive [2020/10/21-10:25:34.487] [null-err-38] [INFO] [dku.utils] - 2020-10-21 10:25:34,486 29757 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:34.488] [null-err-38] [INFO] [dku.utils] - 2020-10-21 10:25:34,487 29757 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:34.488] [null-err-38] [INFO] [dku.utils] - 2020-10-21 10:25:34,487 29757 INFO Executing: ['setfacl', '-RP', '-m', 'u::rwx,g::---,o:---,d:u:dataiku:rwx,u:dataiku:rwx', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######'] [2020/10/21-10:25:34.502] [Thread-25] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:34.509] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Written config to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/config.json [2020/10/21-10:25:34.511] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Starting wrapper: ["sudo","-n","/etc/dataiku-security/#######/execwrapper.sh","execute","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/config.json"] [2020/10/21-10:25:34.615] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Reading pipes from wrapper [2020/10/21-10:25:34.679] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,679 29763 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:34.681] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,681 29763 INFO Allowed group ids: [50003] [2020/10/21-10:25:34.687] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,686 29763 INFO User ####### belongs to groups: [503869135, 50003] [2020/10/21-10:25:34.692] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,691 29763 INFO User ####### belongs to group 50003 (dataiku_python_runner) -> allowed [2020/10/21-10:25:34.692] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,691 29763 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:34.692] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,692 29763 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:34.693] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,692 29763 INFO [BF] Setting up process environment [2020/10/21-10:25:34.693] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,692 29763 INFO [BF] Writing wrapper pipes and pid to wrapper stdout [2020/10/21-10:25:34.693] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Pipes read as bytes: 755 [2020/10/21-10:25:34.693] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Pipes read as bytes: {"pipes": {"stdin": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdin.#######", "stderr": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stderr.#######", "stdout": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdout.#######"}, "pid": 29763, "childPidFile": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/child.pid"} [2020/10/21-10:25:34.694] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Pid read: 29763 [2020/10/21-10:25:34.694] [FRT-33-FlowRunnable] [INFO] [dku.security.process] act.compute_iris_copy_NP - Pipes read: { "stdin": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdin.#######", "stderr": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stderr.#######", "stdout": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdout.#######" } [2020/10/21-10:25:34.695] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,693 29763 INFO [Parent] Started process 29765 [2020/10/21-10:25:34.697] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,697 29765 INFO [Child] pgroup is set [2020/10/21-10:25:34.698] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,697 29765 INFO [Child] opening stdin pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdin.####### [2020/10/21-10:25:34.698] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] opened stdin pipe [2020/10/21-10:25:34.698] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] opening stdout pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stdout.####### [2020/10/21-10:25:34.698] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] opened stdout [2020/10/21-10:25:34.699] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] opening stderr pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/.stderr.####### [2020/10/21-10:25:34.700] [FRT-33-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_iris_copy_NP - Process reads from nothing [2020/10/21-10:25:34.701] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] opened stderr [2020/10/21-10:25:34.704] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] about to close other fd [2020/10/21-10:25:34.705] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] closed other fd [2020/10/21-10:25:34.705] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO [Child] chdired [2020/10/21-10:25:34.705] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,698 29765 INFO setting username=####### uid=503869135 gid=503869135 [2020/10/21-10:25:34.705] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,701 29765 INFO [Child] dropped privileges [2020/10/21-10:25:34.706] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,701 29765 INFO [Child] Checking access to DKUINSTALLDIR and DIP_HOME directories [2020/10/21-10:25:34.706] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,701 29765 INFO [Child] Executing: /appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python : /appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python -u /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/python-exec-wrapper.py /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/script.py [2020/10/21-10:25:34.704] [FRT-33-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_copy_NP - Reporting start of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_copy_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_iris_copy"},"type":"LOCAL_PROCESS","id":"PfHPCeoFYzPan2QM","startTime":1603268734702,"localProcess":{"cpuCurrent":0.0}} [2020/10/21-10:25:34.708] [FRT-33-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_copy_NP - Reporting start of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_copy_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_iris_copy"},"type":"LOCAL_PROCESS","id":"PfHPCeoFYzPan2QM","startTime":1603268734702,"localProcess":{"cpuCurrent":0.0}} [2020/10/21-10:25:34.716] [process-resource-monitor-unkpid-44] [INFO] [dku.security.process] - GET PID CPF=/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/child.pid [2020/10/21-10:25:34.718] [process-resource-monitor-29765-44] [INFO] [dku.usage.computeresource.jek] - Reporting update of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_copy_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_iris_copy"},"type":"LOCAL_PROCESS","id":"PfHPCeoFYzPan2QM","startTime":1603268734702,"localProcess":{"pid":29765,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":5,"vmRSSMB":0,"vmHWMMB":0,"vmRSSAnonMB":0,"vmDataMB":0,"vmSizePeakMB":5,"vmRSSPeakMB":0,"vmRSSTotalMBS":0,"majorFaults":1,"childrenMajorFaults":0}} [2020/10/21-10:25:34.718] [process-resource-monitor-29765-44] [DEBUG] [dku.resource] - Process stats for pid 29765: {"pid":29765,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":5,"vmRSSMB":0,"vmHWMMB":0,"vmRSSAnonMB":0,"vmDataMB":0,"vmSizePeakMB":5,"vmRSSPeakMB":0,"vmRSSTotalMBS":0,"majorFaults":1,"childrenMajorFaults":0} [2020/10/21-10:25:34.865] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO -------------------- [2020/10/21-10:25:34.866] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO Dataiku Python entrypoint starting up [2020/10/21-10:25:34.866] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO executable = /appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python [2020/10/21-10:25:34.866] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO argv = ['/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/python-exec-wrapper.py', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/script.py'] [2020/10/21-10:25:34.867] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO -------------------- [2020/10/21-10:25:34.867] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO Looking for RemoteRunEnvDef in ./remote-run-env-def.json [2020/10/21-10:25:34.867] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO Found RemoteRunEnvDef environment: ./remote-run-env-def.json [2020/10/21-10:25:34.868] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,864 INFO Running a DSS Python recipe locally, uinsetting env [2020/10/21-10:25:34.868] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,865 INFO Setup complete, ready to execute Python code [2020/10/21-10:25:34.868] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,865 INFO Sys path: ['/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######', '/appl/dataiku/dss_data/lib/python', '/appl/dataiku/dataiku-dss-8.0.2/python', '/appl/dataiku/dss_data/code-envs/python/Py36Env/lib64/python36.zip', '/appl/dataiku/dss_data/code-envs/python/Py36Env/lib64/python3.6', '/appl/dataiku/dss_data/code-envs/python/Py36Env/lib64/python3.6/lib-dynload', '/opt/rh/rh-python36/root/usr/lib64/python3.6', '/opt/rh/rh-python36/root/usr/lib/python3.6', '/appl/dataiku/dss_data/code-envs/python/Py36Env/lib/python3.6/site-packages', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/project-python-libs/#######/python'] [2020/10/21-10:25:34.869] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:34,865 INFO Script file: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_iris_copy_NP/python-recipe/#######/script.py [2020/10/21-10:25:37.429] [qtp1906029492-23] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.429] [qtp1906029492-23] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/get-schema [2020/10/21-10:25:37.438] [qtp1906029492-23] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_SCHEMA::#######.iris [2020/10/21-10:25:37.444] [qtp1906029492-23] [INFO] [dku.job.slave] - Reading schema of dataset #######.iris [2020/10/21-10:25:37.444] [qtp1906029492-23] [DEBUG] [dku.jobs] - Command /tintercom/datasets/get-schema processed in 15ms [2020/10/21-10:25:37.455] [qtp1906029492-19] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.455] [qtp1906029492-19] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/read-data [2020/10/21-10:25:37.458] [qtp1906029492-19] [INFO] [dku.job.slave] - Using cached grant: datasetread::READ_DATA::#######.iris [2020/10/21-10:25:37.472] [qtp1906029492-19] [INFO] [dku.datasets.file] - Building Filesystem handler config: {"path":"/appl/dataiku/dss_data/uploads/#######/datasets/iris","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/10/21-10:25:37.473] [qtp1906029492-19] [INFO] [dku.datasets.ftplike] - Enumerating Filesystem dataset prefix= [2020/10/21-10:25:37.473] [qtp1906029492-19] [DEBUG] [dku.fs.local] - Enumerating local filesystem prefix=/ [2020/10/21-10:25:37.473] [qtp1906029492-19] [DEBUG] [dku.fs.local] - Enumeration done nb_paths=1 size=3975 [2020/10/21-10:25:37.473] [qtp1906029492-19] [INFO] [dku.input.push] - USTP: push selection.method=FULL records=-1 ratio=0.02 col=null [2020/10/21-10:25:37.476] [qtp1906029492-19] [INFO] [dku.format] - Extractor run: limit={"maxBytes":-1,"maxRecords":-1,"ordering":{"enabled":false,"rules":[]}} totalRecords=0 [2020/10/21-10:25:37.487] [qtp1906029492-19] [INFO] [dku] - getCompression filename=**iris.csv** [2020/10/21-10:25:37.488] [qtp1906029492-19] [INFO] [dku] - getCompression filename=**iris.csv** [2020/10/21-10:25:37.488] [qtp1906029492-19] [INFO] [dku.format] - Start uncompressed stream: /appl/dataiku/dss_data/uploads/#######/datasets/iris/iris.csv / totalRecsBefore=0 [2020/10/21-10:25:37.488] [qtp1906029492-19] [INFO] [dku] - getCompression filename=**iris.csv** [2020/10/21-10:25:37.501] [qtp1906029492-19] [INFO] [dku.format] - after stream totalComp=3975 totalUncomp=3975 totalRec=150 [2020/10/21-10:25:37.501] [qtp1906029492-19] [INFO] [dku.format] - Extractor run done, totalCompressed=3975 totalRecords=150 [2020/10/21-10:25:37.501] [qtp1906029492-19] [DEBUG] [dku.jobs] - Command /tintercom/datasets/read-data processed in 46ms [2020/10/21-10:25:37.515] [qtp1906029492-21] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.516] [qtp1906029492-21] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/set-schema [2020/10/21-10:25:37.517] [qtp1906029492-21] [INFO] [dku.job.slave] - Trying to obtain grant: dataset::WRITE_SCHEMA::#######.iris_copy [2020/10/21-10:25:37.529] [qtp1906029492-21] [INFO] [dku.job.slave] - Setting schema of dataset #######.iris_copy [2020/10/21-10:25:37.530] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWritingService] - Setting schema of #######.iris_copy [2020/10/21-10:25:37.533] [qtp1906029492-21] [DEBUG] [dku.datasets.managed.helper] - Fixup partitioning, datasetToFixup={"fullName":"#######.iris_copy","model":{"type":"SQLServer","managed":true,"name":"iris_copy","projectKey":"#######","description":"# Iris copy dataset\n\nThis is the same dataset as iris, but now with an approximation of the sepal surface.","shortDesc":"This is the same dataset as iris, but now with an approximation of the sepal surface.","checklists":{"checklists":[]},"checks":[],"customMeta":{"kv":{}},"flowOptions":{"virtualizable":false,"rebuildBehavior":"NORMAL","crossProjectBuildBehavior":"DEFAULT"},"readWriteOptions":{"preserveOrder":false,"writeBuckets":1,"forceSingleOutputFile":false,"defaultReadOrdering":{"enabled":false,"rules":[]}},"partitioning":{"ignoreNonMatchingFile":false,"considerMissingRequestedPartitionsAsEmpty":false,"dimensions":[]},"versionTag":{"versionNumber":4,"lastModifiedBy":{"login":"StamA3"},"lastModifiedOn":1572954537901},"creationTag":{"versionNumber":0,"lastModifiedBy":{"login":"StamA3"},"lastModifiedOn":1571744218312},"tags":[],"params":{"connection":"#######","notReadyIfEmpty":false,"mode":"table","partitioningType":"custom","normalizeDoubles":true,"table":"${projectKey}_iris_copy","schema":"dbo","tableCreationMode":"auto","writeInsertBatchSize":10000,"writeJDBCBadDataBehavior":"DISCARD_ROW","readColsWithUnknownTzAsDates":false,"readSQLDateColsAsDSSDates":true},"schema":{"columns":[{"name":"sepal_length","type":"double"},{"name":"sepal_width","type":"double"},{"name":"petal_length","type":"double"},{"name":"petal_width","type":"double"},{"name":"variety","type":"string"},{"name":"sepal_surface","type":"double"}],"userModified":false},"metrics":{"probes":[{"type":"basic","enabled":true,"computeOnBuildMode":"PARTITION","meta":{"name":"Basic data","level":0},"configuration":{}},{"type":"records","enabled":true,"computeOnBuildMode":"NO","meta":{"name":"Record count","level":0},"configuration":{}}],"engineConfig":{"padRunsWithMetrics":false,"hive":{"active":true,"extraConf":[]},"basic":{},"dss":{"active":true,"selection":{"useMemTable":false,"filter":{"distinct":false,"enabled":false},"partitionSelectionMethod":"ALL","latestPartitionsN":1,"ordering":{"enabled":false,"rules":[]},"samplingMethod":"FULL","maxRecords":-1,"targetRatio":0.02,"withinFirstN":-1,"maxReadUncompressedBytes":-1}},"sql":{"active":true},"impala":{"active":true},"spark":{"active":true,"extraConf":[]},"python":{}},"displayedState":{"columns":[],"metrics":["basic:COUNT_COLUMNS","records:COUNT_RECORDS"]}},"metricsChecks":{"runOnBuild":false,"checks":[],"displayedState":{"checks":[]}},"customFields":{}},"partitioning":{"ignoreNonMatchingFile":false,"considerMissingRequestedPartitionsAsEmpty":false,"dimensions":[]}} schemaToFixup={"columns":[{"name":"sepal_length","type":"double"}, {"name":"sepal_width","type":"double"}, {"name":"petal_length","type":"double"}, {"name":"petal_width","type":"double"}, {"name":"variety","type":"string"}, {"name":"sepal_surface","type":"double"} ], "userModified": false } [2020/10/21-10:25:37.534] [qtp1906029492-21] [DEBUG] [dku.datasets.managed.helper] - After partitioning fixup, got schema: {"columns":[{"name":"sepal_length","type":"double"}, {"name":"sepal_width","type":"double"}, {"name":"petal_length","type":"double"}, {"name":"petal_width","type":"double"}, {"name":"variety","type":"string"}, {"name":"sepal_surface","type":"double"} ], "userModified": false } [2020/10/21-10:25:37.550] [qtp1906029492-21] [INFO] [dip.connections.sqlserver] - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:37.558] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWritingService] - Schema was not modified [2020/10/21-10:25:37.559] [qtp1906029492-21] [INFO] [dku.job.slave] - Propagating new schema of #######.iris_copy to backend [2020/10/21-10:25:37.585] [qtp1906029492-21] [DEBUG] [dku.jobs] - Command /tintercom/datasets/set-schema processed in 69ms [2020/10/21-10:25:37.589] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,589 INFO Initializing dataset writer for dataset #######.iris_copy [2020/10/21-10:25:37.591] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,589 INFO Initializing write session [2020/10/21-10:25:37.594] [qtp1906029492-24] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.594] [qtp1906029492-24] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/init-write-session [2020/10/21-10:25:37.609] [qtp1906029492-24] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWritingService] - Init write session: ####### [2020/10/21-10:25:37.609] [qtp1906029492-24] [DEBUG] [dku.jobs] - Command /tintercom/datasets/init-write-session processed in 15ms [2020/10/21-10:25:37.616] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,615 INFO Starting RemoteStreamWriter [2020/10/21-10:25:37.616] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,615 INFO Initializing write data stream (#######) [2020/10/21-10:25:37.617] [qtp1906029492-20] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.617] [qtp1906029492-20] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/wait-write-session [2020/10/21-10:25:37.619] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Remote Stream Writer: start generate [2020/10/21-10:25:37.619] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Waiting for data to send ... [2020/10/21-10:25:37.619] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Sending data (6594) [2020/10/21-10:25:37.620] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Waiting for data to send ... [2020/10/21-10:25:37.619] [qtp1906029492-21] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:37.620] [qtp1906029492-21] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/push-data [2020/10/21-10:25:37.620] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Remote Stream Writer closed [2020/10/21-10:25:37.620] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:37,619 INFO Got end mark, ending send [2020/10/21-10:25:37.625] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWriter] - Creating output writer [2020/10/21-10:25:37.626] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWriter] - Initializing output writer [2020/10/21-10:25:37.628] [qtp1906029492-21] [INFO] [dip.connections.sqlserver] - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) 48.170: [GC (Metadata GC Threshold) [PSYoungGen: 66256K->13509K(136704K)] 77565K->24819K(179712K), 0.0157635 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 48.186: [Full GC (Metadata GC Threshold) [PSYoungGen: 13509K->0K(136704K)] [ParOldGen: 11309K->18460K(61952K)] 24819K->18460K(198656K), [Metaspace: 35019K->35019K(1081344K)], 0.0924204 secs] [Times: user=0.12 sys=0.03, real=0.09 secs] [2020/10/21-10:25:37.753] [Thread-13] [INFO] [dku.job.slave] - Sending status update [2020/10/21-10:25:37.766] [Thread-13] [INFO] [dku.job.slave] - Status update sent [2020/10/21-10:25:37.771] [qtp1906029492-21] [INFO] [dip.krb.login] - Logging in to Kerberos, principal=MSSQLSvc/#######.####### keytab=/appl/dataiku/keytab/#######.keytab [2020/10/21-10:25:37.877] [qtp1906029492-21] [INFO] [dip.krb.login] - Successfully logged subject = [MSSQLSvc/#######.#######@#######], TGT end time = Wed Oct 21 20:25:37 CEST 2020 [2020/10/21-10:25:37.911] [qtp1906029492-21] [INFO] [dku.connections.sql.provider] - Connecting to jdbc:sqlserver://#######.####### with props: {"integratedSecurity":"true","instanceName":"DEINSTANCE00","authenticationScheme":"JavaKerberos","portNumber":"1433","databaseName":"#######"} conn=#######-gBemV9g [2020/10/21-10:25:37.912] [qtp1906029492-21] [DEBUG] [dku.connections.sql.driver] - Driver version 7.2 [2020/10/21-10:25:37.912] [qtp1906029492-21] [INFO] [dip.krb.login] - Retrieving impersonated Kerberos credentials for ####### [2020/10/21-10:25:38.189] [qtp1906029492-21] [INFO] [dku.connections.sql.provider] - Driver: Microsoft JDBC Driver 7.2 for SQL Server (JDBC 4.2) 7.2.2.0 (7.2) [2020/10/21-10:25:38.190] [qtp1906029492-21] [INFO] [dku.connections.sql.provider] - Database: Microsoft SQL Server 13.00.5698 (13.0) rowSize=8060 stmts=0 [2020/10/21-10:25:38.196] [qtp1906029492-21] [INFO] [dku.resourceusage] - Reporting start of CRU:{"type":"SQL_CONNECTION","id":"NKVt86bhsBkcGpm5","startTime":1603268738183,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:38.196] [qtp1906029492-21] [INFO] [dku.usage.computeresource.jek] - Reporting start of resource usage: {"type":"SQL_CONNECTION","id":"NKVt86bhsBkcGpm5","startTime":1603268738183,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:38.198] [qtp1906029492-21] [INFO] [dku.sql.generic] - Dropping table [2020/10/21-10:25:38.198] [qtp1906029492-21] [INFO] [dku.dataset.sql] - Executing statement: [2020/10/21-10:25:38.199] [qtp1906029492-21] [INFO] [dku.dataset.sql] - DROP TABLE "dbo"."#######_iris_copy" [2020/10/21-10:25:38.209] [qtp1906029492-21] [INFO] [dku.dataset.sql] - Statement done [2020/10/21-10:25:38.210] [qtp1906029492-21] [INFO] [dku.sql.generic] - Creating table [2020/10/21-10:25:38.212] [qtp1906029492-21] [INFO] [dku.dataset.sql] - Executing statements: [2020/10/21-10:25:38.212] [qtp1906029492-21] [INFO] [dku.dataset.sql] - CREATE TABLE "dbo"."#######_iris_copy" ( "sepal_length" float, "sepal_width" float, "petal_length" float, "petal_width" float, "variety" nvarchar(max), "sepal_surface" float ) [2020/10/21-10:25:38.221] [qtp1906029492-21] [INFO] [dku.dataset.sql] - Executing statement: CREATE TABLE "dbo"."#######_iris_copy" ( "sepal_length" float, "sepal_width" float, "petal_length" float, "petal_width" float, "variety" nvarchar(max), "sepal_surface" float ) [2020/10/21-10:25:38.224] [qtp1906029492-21] [INFO] [dku.dataset.sql] - Statement done [2020/10/21-10:25:38.224] [qtp1906029492-21] [DEBUG] [dku.connections.sql.provider] - Commit conn=#######-gBemV9g [2020/10/21-10:25:38.268] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWriter] - Done initializing output writer [2020/10/21-10:25:38.291] [qtp1906029492-21] [INFO] [dku.output.sql] - committing, appended 150 failedRows=0 rowsWithFailedCells=0 [2020/10/21-10:25:38.292] [qtp1906029492-21] [INFO] [dku.output.sql] - Executing final batch [2020/10/21-10:25:38.349] [qtp1906029492-21] [INFO] [dku.output.sql] - Executed final batch [2020/10/21-10:25:38.351] [qtp1906029492-21] [DEBUG] [dku.connections.sql.provider] - Commit conn=#######-gBemV9g [2020/10/21-10:25:38.353] [qtp1906029492-21] [DEBUG] [dku.connections.sql.provider] - Close conn=#######-gBemV9g [2020/10/21-10:25:38.354] [qtp1906029492-21] [INFO] [dku.resourceusage] - Reporting completion of CRU:{"type":"SQL_CONNECTION","id":"NKVt86bhsBkcGpm5","startTime":1603268738183,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:38.354] [qtp1906029492-21] [INFO] [dku.usage.computeresource.jek] - Reporting completion of resource usage: {"type":"SQL_CONNECTION","id":"NKVt86bhsBkcGpm5","startTime":1603268738183,"endTime":1603268738354,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:38.354] [qtp1906029492-21] [INFO] [dku.output.sql] - Transaction done [2020/10/21-10:25:38.354] [qtp1906029492-21] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWritingService] - Pushed data to write session ####### : 150 rows [2020/10/21-10:25:38.355] [qtp1906029492-21] [DEBUG] [dku.jobs] - Command /tintercom/datasets/push-data processed in 736ms [2020/10/21-10:25:38.358] [qtp1906029492-20] [INFO] [com.dataiku.dip.dataflow.streaming.DatasetWritingService] - Finished write session: ####### [2020/10/21-10:25:38.359] [qtp1906029492-20] [DEBUG] [dku.jobs] - Command /tintercom/datasets/wait-write-session processed in 742ms [2020/10/21-10:25:38.364] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:38,363 INFO Check if spark is available [2020/10/21-10:25:38.364] [null-err-42] [INFO] [dku.utils] - 2020-10-21 10:25:38,364 INFO Not stopping a spark context: No module named 'pyspark' [2020/10/21-10:25:38.365] [null-out-41] [INFO] [dku.utils] - 150 rows successfully written (#######) [2020/10/21-10:25:38.491] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:38,491 29763 INFO [Child] Process 29765 exited with exit=0 signal=0 [2020/10/21-10:25:38.491] [wrapper-stderr-40] [INFO] [dku.utils] - 2020-10-21 10:25:38,491 29763 INFO Full child code: 0 [2020/10/21-10:25:38.504] [FRT-33-FlowRunnable] [WARN] [dku.resource] act.compute_iris_copy_NP - stat file for pid 29765 does not exist. Process died? [2020/10/21-10:25:38.504] [FRT-33-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_copy_NP - Reporting completion of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_copy_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_iris_copy"},"type":"LOCAL_PROCESS","id":"PfHPCeoFYzPan2QM","startTime":1603268734702,"localProcess":{"pid":29765,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":5,"vmRSSMB":0,"vmHWMMB":0,"vmRSSAnonMB":0,"vmDataMB":0,"vmSizePeakMB":5,"vmRSSPeakMB":0,"vmRSSTotalMBS":0,"majorFaults":1,"childrenMajorFaults":0}} [2020/10/21-10:25:38.505] [FRT-33-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_copy_NP - Reporting completion of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_copy_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_iris_copy"},"type":"LOCAL_PROCESS","id":"PfHPCeoFYzPan2QM","startTime":1603268734702,"endTime":1603268738505,"localProcess":{"pid":29765,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36Env/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":5,"vmRSSMB":0,"vmHWMMB":0,"vmRSSAnonMB":0,"vmDataMB":0,"vmSizePeakMB":5,"vmRSSPeakMB":0,"vmRSSTotalMBS":0,"majorFaults":1,"childrenMajorFaults":0}} [2020/10/21-10:25:38.505] [FRT-33-FlowRunnable] [INFO] [dku.flow.python] act.compute_iris_copy_NP - Execution of user's Python code complete [2020/10/21-10:25:38.509] [FRT-33-FlowRunnable] [INFO] [dku.flow.activity] act.compute_iris_copy_NP - Run thread done for activity compute_iris_copy_NP [2020/10/21-10:25:38.646] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - activity is finished [2020/10/21-10:25:38.647] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Executing default post-activity lifecycle hook [2020/10/21-10:25:38.651] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Activity successful, computing metrics and running checks [2020/10/21-10:25:38.920] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Activity checks produced 0 values [2020/10/21-10:25:38.921] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Activity is successful, computing timestamps to propagate [2020/10/21-10:25:38.925] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Activity is successful, propagating 3 timestamps [2020/10/21-10:25:38.926] [ActivityExecutor-28] [INFO] [dku.timestamps.sql] running compute_iris_copy_NP - Starting to propagate 3 hashes [2020/10/21-10:25:38.933] [ActivityExecutor-28] [DEBUG] [dku.connections.sql.provider] running compute_iris_copy_NP - Commit conn=dssdb-h2-flow_state-QkH5bAw [2020/10/21-10:25:38.934] [ActivityExecutor-28] [INFO] [dku.timestamps.sql] running compute_iris_copy_NP - Hashes propagated in 8 ms [2020/10/21-10:25:38.934] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Removing samples for #######.iris_copy [2020/10/21-10:25:38.936] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_iris_copy_NP - Done post-activity tasks [2020/10/21-10:25:38.957] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] - About to run compute_#######_NP [2020/10/21-10:25:38.973] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] running compute_#######_NP - Allocated a slot for this activity! [2020/10/21-10:25:38.973] [ActivityExecutor-28] [INFO] [dku.flow.jobrunner] running compute_#######_NP - Run activity [2020/10/21-10:25:38.979] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - Executing default pre-activity lifecycle hook [2020/10/21-10:25:38.990] [ActivityExecutor-28] [INFO] [dku.managedfolders.handler] running compute_#######_NP - Create provider for #######.####### with path #######/####### [2020/10/21-10:25:38.993] [ActivityExecutor-28] [INFO] [dku.managedfolders.handler] running compute_#######_NP - Ensured folder for root of managed folder [2020/10/21-10:25:38.994] [ActivityExecutor-28] [INFO] [dku.fs.local] running compute_#######_NP - Making folder contents belong solely to DSS [2020/10/21-10:25:38.997] [ActivityExecutor-28] [INFO] [dku.security.fsacl] running compute_#######_NP - chmod /appl/dataiku/dss_data/RADIO_files/#######/#######: ["OWNER_READ","OWNER_EXECUTE","OWNER_WRITE"] [2020/10/21-10:25:39.002] [ActivityExecutor-28] [DEBUG] [dku.security.fsacl] running compute_#######_NP - exec setfacl: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls setfacl --path /appl/dataiku/dss_data/RADIO_files/#######/####### --perm m::rwx --recursive [2020/10/21-10:25:39.209] [null-err-47] [INFO] [dku.utils] - 2020-10-21 10:25:39,209 29790 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:39.210] [null-err-47] [INFO] [dku.utils] - 2020-10-21 10:25:39,210 29790 INFO Allowed path: /appl/dataiku/dss_data/RADIO_files/#######/####### in /appl/dataiku/dss_data [2020/10/21-10:25:39.211] [null-err-47] [INFO] [dku.utils] - 2020-10-21 10:25:39,210 29790 INFO Executing: ['setfacl', '-RP', '-m', 'm::rwx', '/appl/dataiku/dss_data/RADIO_files/#######/#######'] [2020/10/21-10:25:39.227] [Thread-33] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:39.229] [ActivityExecutor-28] [INFO] [dku.fs.local] running compute_#######_NP - Making folder contents writable to user [2020/10/21-10:25:39.229] [ActivityExecutor-28] [INFO] [dku.utils.fsacl] running compute_#######_NP - Impersonating: FS granting additional access to ####### [2020/10/21-10:25:39.233] [ActivityExecutor-28] [DEBUG] [dku.security.fsacl] running compute_#######_NP - exec setfacl: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls setfacl --path /appl/dataiku/dss_data/RADIO_files/#######/####### --perm d:u:#######:rwx --perm d:u:dataiku:rwx --perm u:#######:rwx --perm u:dataiku:rwx --affected-user ####### --recursive [2020/10/21-10:25:39.269] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] - About to run compute_iris_by_variety_NP [2020/10/21-10:25:39.279] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] running compute_iris_by_variety_NP - Allocated a slot for this activity! [2020/10/21-10:25:39.279] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] running compute_iris_by_variety_NP - Run activity [2020/10/21-10:25:39.283] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Executing default pre-activity lifecycle hook [2020/10/21-10:25:39.284] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Checking if sources are ready [2020/10/21-10:25:39.307] [ActivityExecutor-29] [INFO] [dku.dataset.hash] running compute_iris_by_variety_NP - managed non-FS dataset, computed new hash for #######.iris_copy/NP: lrGkMnIWiQzvZRnRkyXWTA-IbjtGOE45fzhrsaXVTBZfw, based on 2 propagated from upstream [2020/10/21-10:25:39.308] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Checked source readiness #######.iris_copy -> true [2020/10/21-10:25:39.309] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Computing hashes to propagate BEFORE activity [2020/10/21-10:25:39.313] [ActivityExecutor-29] [INFO] [dku.dataset.hash] running compute_iris_by_variety_NP - managed non-FS dataset, computed new hash for #######.iris_copy/NP: lrGkMnIWiQzvZRnRkyXWTA-IbjtGOE45fzhrsaXVTBZfw, based on 2 propagated from upstream [2020/10/21-10:25:39.314] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Recorded 1 hashes before activity run [2020/10/21-10:25:39.315] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Building recipe runner of type [2020/10/21-10:25:39.323] [ActivityExecutor-29] [INFO] [dku.recipes.group] running compute_iris_by_variety_NP - SET PAYLOAD: { "preFilter": { "distinct": false, "enabled": false }, "keys": [ { "countDistinct": false, "min": false, "avg": false, "last": false, "max": false, "column": "variety", "count": false, "sum": false, "concat": false, "type": "string", "stddev": false, "first": false } ], "values": [ { "last": false, "max": false, "firstLastNotNull": false, "column": "sepal_length", "count": false, "$idx": 0, "sum": false, "concat": false, "type": "double", "concatDistinct": false, "sum2": false, "min": false, "countDistinct": false, "avg": false, "stddev": false, "first": false }, { "last": false, "max": false, "firstLastNotNull": false, "column": "sepal_width", "count": false, "$idx": 1, "sum": false, "concat": false, "type": "double", "concatDistinct": false, "sum2": false, "min": false, "countDistinct": false, "avg": false, "stddev": false, "first": false }, { "last": false, "max": false, "firstLastNotNull": false, "column": "petal_length", "count": false, "$idx": 2, "sum": false, "concat": false, "type": "double", "concatDistinct": false, "sum2": false, "min": true, "countDistinct": false, "avg": false, "stddev": false, "first": false }, { "last": false, "max": true, "firstLastNotNull": false, "column": "petal_width", "count": false, "$idx": 3, "sum": false, "concat": false, "type": "double", "concatDistinct": false, "sum2": false, "min": false, "countDistinct": false, "avg": false, "stddev": false, "first": false }, { "last": false, "max": false, "firstLastNotNull": false, "column": "sepal_surface", "count": false, "$idx": 4, "sum": false, "concat": false, "type": "double", "concatDistinct": false, "sum2": false, "min": false, "countDistinct": false, "avg": true, "$selected": true, "stddev": false, "first": false } ], "globalCount": false, "engineParams": { "hive": { "skipPrerunValidate": false, "hiveconf": [], "inheritConf": "default", "addDkuUdf": false, "executionEngine": "HIVESERVER2" }, "impala": { "forceStreamMode": true }, "lowerCaseSchemaIfEngineRequiresIt": true, "sparkSQL": { "pipelineAllowMerge": true, "useGlobalMetastore": false, "pipelineAllowStart": true, "readParams": { "map": {} }, "overwriteOutputSchema": false, "executionEngine": "SPARK_SUBMIT", "sparkConfig": { "inheritConf": "default", "conf": [] } } }, "engineType": "SQL", "enlargeYourBits": true, "outputColumnNameOverrides": {}, "computedColumns": [], "postFilter": { "$status": { "schema": { "columns": [ { "name": "variety", "type": "string" }, { "name": "petal_length_min", "type": "double" }, { "name": "petal_width_max", "type": "double" }, { "name": "sepal_surface_avg", "type": "double" } ], "userModified": false } }, "distinct": false, "enabled": false } } [2020/10/21-10:25:39.354] [ActivityExecutor-29] [INFO] [com.dataiku.dip.hive.HiveConfigurator] running compute_iris_by_variety_NP - Hive support is disabled (no hadoop) [2020/10/21-10:25:39.354] [ActivityExecutor-29] [INFO] [com.dataiku.dip.impala.ImpalaConfigurator] running compute_iris_by_variety_NP - Impala support is disabled (no hadoop) [2020/10/21-10:25:39.358] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.373] [ActivityExecutor-29] [INFO] [dku.recipes.visualsql] running compute_iris_by_variety_NP - User requested engine: SQL [2020/10/21-10:25:39.373] [ActivityExecutor-29] [INFO] [dku.recipes.grouping.status] running compute_iris_by_variety_NP - Computing engine status for grouping recipe [2020/10/21-10:25:39.374] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.381] [ActivityExecutor-29] [INFO] [dku.recipes.visualsql] running compute_iris_by_variety_NP - User requested engine: SQL [2020/10/21-10:25:39.382] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.383] [ActivityExecutor-29] [INFO] [dku.recipe.visual] running compute_iris_by_variety_NP - Selected engine type: SQL [2020/10/21-10:25:39.395] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.401] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.402] [ActivityExecutor-29] [INFO] [dip.connections.sqlserver] running compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.403] [ActivityExecutor-29] [INFO] [dku.recipes.sql] running compute_iris_by_variety_NP - Substituting variables in SQL query : { "tbl:iris_by_variety": "\"dbo\".\"#######_iris_by_variety\"", "schema:iris_by_variety": "\"dbo\"", "tbl:iris_copy": "\"dbo\".\"#######_iris_copy\"", "schema:iris_copy": "\"dbo\"" } [2020/10/21-10:25:39.438] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,437 29798 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:39.439] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,437 29798 INFO Allowed path: /appl/dataiku/dss_data/RADIO_files/#######/####### in /appl/dataiku/dss_data [2020/10/21-10:25:39.439] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,437 29798 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:39.442] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,441 29798 INFO Allowed group ids: [50003] [2020/10/21-10:25:39.447] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,447 29798 INFO User ####### belongs to groups: [503869135, 50003] [2020/10/21-10:25:39.449] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,448 29798 INFO User ####### belongs to group 50003 (dataiku_python_runner) -> allowed [2020/10/21-10:25:39.449] [null-err-50] [INFO] [dku.utils] - 2020-10-21 10:25:39,448 29798 INFO Executing: ['setfacl', '-RP', '-m', 'd:u:#######:rwx,d:u:dataiku:rwx,u:#######:rwx,u:dataiku:rwx', '/appl/dataiku/dss_data/RADIO_files/#######/#######'] [2020/10/21-10:25:39.467] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Recipe runner built, will use 1 thread(s) [2020/10/21-10:25:39.471] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Starting execution thread: com.dataiku.dip.dataflow.exec.grouping.GroupingRecipeRunner@4ff0b4e9 [2020/10/21-10:25:39.471] [Thread-36] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:39.472] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - Checking if sources are ready [2020/10/21-10:25:39.477] [ActivityExecutor-28] [INFO] [dku.dataset.hash] running compute_#######_NP - managed non-FS dataset, computed new hash for #######.iris_copy/NP: lrGkMnIWiQzvZRnRkyXWTA-IbjtGOE45fzhrsaXVTBZfw, based on 2 propagated from upstream [2020/10/21-10:25:39.477] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - Checked source readiness #######.iris_copy -> true [2020/10/21-10:25:39.478] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Computing hashes to propagate BEFORE activity [2020/10/21-10:25:39.486] [ActivityExecutor-28] [INFO] [dku.dataset.hash] running compute_#######_NP - managed non-FS dataset, computed new hash for #######.iris_copy/NP: lrGkMnIWiQzvZRnRkyXWTA-IbjtGOE45fzhrsaXVTBZfw, based on 2 propagated from upstream [2020/10/21-10:25:39.486] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Recorded 1 hashes before activity run [2020/10/21-10:25:39.487] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Building recipe runner of type [2020/10/21-10:25:39.488] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_iris_by_variety_NP - Execution threads started, waiting for activity end [2020/10/21-10:25:39.490] [ActivityExecutor-28] [DEBUG] [dku.job.activity] running compute_#######_NP - Filling source sizes [2020/10/21-10:25:39.491] [ActivityExecutor-28] [DEBUG] [dku.job.activity] running compute_#######_NP - Done filling source sizes [2020/10/21-10:25:39.491] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Recipe runner built, will use 1 thread(s) [2020/10/21-10:25:39.491] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Starting execution thread: com.dataiku.dip.recipes.code.python.PythonRecipeRunner@49fbe542 [2020/10/21-10:25:39.493] [ActivityExecutor-28] [DEBUG] [dku.flow.activity] running compute_#######_NP - Execution threads started, waiting for activity end [2020/10/21-10:25:39.494] [FRT-52-FlowRunnable] [INFO] [dku.flow.activity] act.compute_iris_by_variety_NP - Run thread for activity compute_iris_by_variety_NP starting [2020/10/21-10:25:39.494] [FRT-52-FlowRunnable] [INFO] [dku.recipe.visual] act.compute_iris_by_variety_NP - Selected executor: com.dataiku.dip.dataflow.exec.MultiEngineRecipeRunner$2 [2020/10/21-10:25:39.495] [FRT-52-FlowRunnable] [INFO] [dku.recipes.sql] act.compute_iris_by_variety_NP - Running the SQL query recipe in full-SQL mode [2020/10/21-10:25:39.495] [FRT-52-FlowRunnable] [INFO] [dku.flow.sql] act.compute_iris_by_variety_NP - Running the SQL query recipe in full-SQL mode [2020/10/21-10:25:39.496] [FRT-52-FlowRunnable] [INFO] [dip.connections.sqlserver] act.compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.497] [FRT-52-FlowRunnable] [INFO] [dip.sql.addinsert] act.compute_iris_by_variety_NP - Putting query in INSERT INTO '${projectKey}_iris_by_variety': SELECT "variety" AS "variety", MIN("petal_length") AS "petal_length_min", MAX("petal_width") AS "petal_width_max", AVG("sepal_surface") AS "sepal_surface_avg" FROM ( SELECT "sepal_length" AS "sepal_length", "sepal_width" AS "sepal_width", "petal_length" AS "petal_length", "petal_width" AS "petal_width", "variety" AS "variety", "sepal_surface" AS "sepal_surface" FROM "dbo"."#######_iris_copy" ) "dku__beforegrouping" GROUP BY "variety" [2020/10/21-10:25:39.500] [FRT-52-FlowRunnable] [INFO] [dip.connections.sqlserver] act.compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.501] [FRT-52-FlowRunnable] [INFO] [dip.connections.sqlserver] act.compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.501] [FRT-52-FlowRunnable] [INFO] [dku.recipes.sql] act.compute_iris_by_variety_NP - Substituting variables in SQL query : { "tbl:iris_by_variety": "\"dbo\".\"#######_iris_by_variety\"", "schema:iris_by_variety": "\"dbo\"", "tbl:iris_copy": "\"dbo\".\"#######_iris_copy\"", "schema:iris_copy": "\"dbo\"" } [2020/10/21-10:25:39.502] [FRT-52-FlowRunnable] [INFO] [dip.connections.sqlserver] act.compute_iris_by_variety_NP - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:39.506] [FRT-53-FlowRunnable] [INFO] [dku.flow.activity] act.compute_#######_NP - Run thread for activity compute_#######_NP starting [2020/10/21-10:25:39.508] [FRT-53-FlowRunnable] [INFO] [dku.flow.python] act.compute_#######_NP - Starting execution of user's Python code [2020/10/21-10:25:39.509] [FRT-53-FlowRunnable] [INFO] [dku.venv.selector] act.compute_#######_NP - Select code env lang=PYTHON projectSelection={"mode":"INHERIT","preventOverride":false} globalDefault=null [2020/10/21-10:25:39.507] [FRT-52-FlowRunnable] [INFO] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Connecting to jdbc:sqlserver://#######.####### with props: {"integratedSecurity":"true","instanceName":"DEINSTANCE00","authenticationScheme":"JavaKerberos","portNumber":"1433","databaseName":"#######"} conn=#######-EEa3lNe [2020/10/21-10:25:39.511] [FRT-53-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_#######_NP - Dumping Python script to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/script.py [2020/10/21-10:25:39.512] [FRT-52-FlowRunnable] [DEBUG] [dku.connections.sql.driver] act.compute_iris_by_variety_NP - Driver version 7.2 [2020/10/21-10:25:39.514] [FRT-52-FlowRunnable] [INFO] [dip.krb.login] act.compute_iris_by_variety_NP - Retrieving impersonated Kerberos credentials for ####### [2020/10/21-10:25:39.524] [FRT-53-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_#######_NP - EXTERNAL LIBS FROM ####### is {"gitReferences":{},"pythonPath":["python"],"rsrcPath":["R"],"importLibrariesFromProjects":[]} [2020/10/21-10:25:39.525] [FRT-53-FlowRunnable] [DEBUG] [dku.code.projectLibs] act.compute_#######_NP - Impersonation enabled, copying project ####### lib chunk /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/python to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/project-python-libs/#######/python [2020/10/21-10:25:39.526] [FRT-53-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_#######_NP - chunkFolder is /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/R [2020/10/21-10:25:39.527] [FRT-53-FlowRunnable] [DEBUG] [dku.code.projectLibs] act.compute_#######_NP - Impersonation enabled, copying project lib chunk /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/localconfig/projects/#######/lib/R to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/project-r-src/R [2020/10/21-10:25:39.529] [FRT-53-FlowRunnable] [INFO] [xxx] act.compute_#######_NP - RSRC PATH: ["/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/project-r-src/R"] [2020/10/21-10:25:39.533] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Writing dku-exec-env for local execution in /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/remote-run-env-def.json [2020/10/21-10:25:39.534] [FRT-53-FlowRunnable] [INFO] [dku.code.envs.resolution] act.compute_#######_NP - Executing Python activity in env: Py36-Admin [2020/10/21-10:25:39.536] [FRT-53-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_#######_NP - Execute activity command: ["/appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python","-u","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/python-exec-wrapper.py","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/script.py"] [2020/10/21-10:25:39.537] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Run command insecurely, from user dataiku [2020/10/21-10:25:39.539] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Setting exclusive access on /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### [2020/10/21-10:25:39.540] [FRT-53-FlowRunnable] [DEBUG] [dku.security.fsacl] act.compute_#######_NP - exec chown: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls chown --path /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### --owner ####### [2020/10/21-10:25:39.597] [FRT-52-FlowRunnable] [INFO] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Driver: Microsoft JDBC Driver 7.2 for SQL Server (JDBC 4.2) 7.2.2.0 (7.2) [2020/10/21-10:25:39.599] [FRT-52-FlowRunnable] [INFO] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Database: Microsoft SQL Server 13.00.5698 (13.0) rowSize=8060 stmts=0 [2020/10/21-10:25:39.600] [FRT-52-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_by_variety_NP - Reporting start of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_CONNECTION","id":"#######","startTime":1603268739597,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:39.601] [FRT-52-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_by_variety_NP - Reporting start of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_CONNECTION","id":"#######","startTime":1603268739597,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:39.602] [FRT-52-FlowRunnable] [INFO] [dku.sql.generic] act.compute_iris_by_variety_NP - Dropping table [2020/10/21-10:25:39.602] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - Executing statement: [2020/10/21-10:25:39.602] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - DROP TABLE "dbo"."#######_iris_by_variety" [2020/10/21-10:25:39.611] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - Statement done [2020/10/21-10:25:39.612] [FRT-52-FlowRunnable] [INFO] [dku.sql.generic] act.compute_iris_by_variety_NP - Creating table [2020/10/21-10:25:39.612] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - Executing statements: [2020/10/21-10:25:39.613] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - CREATE TABLE "dbo"."#######_iris_by_variety" ( "variety" nvarchar(max), "petal_length_min" float, "petal_width_max" float, "sepal_surface_avg" float ) [2020/10/21-10:25:39.613] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - Executing statement: CREATE TABLE "dbo"."#######_iris_by_variety" ( "variety" nvarchar(max), "petal_length_min" float, "petal_width_max" float, "sepal_surface_avg" float ) [2020/10/21-10:25:39.616] [FRT-52-FlowRunnable] [INFO] [dku.dataset.sql] act.compute_iris_by_variety_NP - Statement done [2020/10/21-10:25:39.616] [FRT-52-FlowRunnable] [DEBUG] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Commit conn=#######-EEa3lNe [2020/10/21-10:25:39.622] [FRT-52-FlowRunnable] [INFO] [dku.queries.executionplan] act.compute_iris_by_variety_NP - Compute execution plan [2020/10/21-10:25:39.623] [FRT-52-FlowRunnable] [WARN] [dku.queries.executionplan] act.compute_iris_by_variety_NP - Computing execution plan inside a transaction [2020/10/21-10:25:39.657] [FRT-52-FlowRunnable] [INFO] [dku.flow.sql] act.compute_iris_by_variety_NP - Execution plan: SELECT "variety" AS "variety", MIN("petal_length") AS "petal_length_min", MAX("petal_width") AS "petal_width_max", AVG("sepal_surface") AS "sepal_surface_avg" FROM ( SELECT "sepal_length" AS "sepal_length", "sepal_width" AS "sepal_width", "petal_length" AS "petal_length", "petal_width" AS "petal_width", "variety" AS "variety", "sepal_surface" AS "sepal_surface" FROM "dbo"."#######_iris_copy" ) "dku__beforegrouping" GROUP BY "variety" ; 1 ; 1 ; 0 ; ; ; 1 ; ; 3.0 ; ; ; ; 0.017332148 ; ; ; SELECT ; 0 ; |--Compute Scalar(DEFINE:([Expr1005]=CASE WHEN [Expr1012]=(0) THEN NULL ELSE [Expr1013]/CONVERT_IMPLICIT(float(53),[Expr1012],0) END)) ; 1 ; 2 ; 1 ; Compute Scalar ; Compute Scalar ; DEFINE:([Expr1005]=CASE WHEN [Expr1012]=(0) THEN NULL ELSE [Expr1013]/CONVERT_IMPLICIT(float(53),[Expr1012],0) END) ; [Expr1005]=CASE WHEN [Expr1012]=(0) THEN NULL ELSE [Expr1013]/CONVERT_IMPLICIT(float(53),[Expr1012],0) END ; 3.0 ; 0.0 ; 0.0 ; 103 ; 0.017332148 ; [#######].[dbo].[#######_iris_copy].[variety], [Expr1003], [Expr1004], [Expr1005] ; ; PLAN_ROW ; 0 ; 1.0 |--Stream Aggregate(GROUP BY:([#######].[dbo].[#######_iris_copy].[variety]) DEFINE:([Expr1003]=MIN([#######].[dbo].[#######_iris_copy].[petal_length]), [Expr1004]=MAX([#######].[dbo].[#######_iris_copy].[petal_width]), [Expr1012]=COUNT_BIG([#######].[dbo].[#######_iris_copy].[sepal_surface]), [Expr1013]=SUM([#######].[dbo].[#######_iris_copy].[sepal_surface]))) ; 1 ; 3 ; 2 ; Stream Aggregate ; Aggregate ; GROUP BY:([#######].[dbo].[#######_iris_copy].[variety]) ; [Expr1003]=MIN([#######].[dbo].[#######_iris_copy].[petal_length]), [Expr1004]=MAX([#######].[dbo].[#######_iris_copy].[petal_width]), [Expr1012]=COUNT_BIG([#######].[dbo].[#######_iris_copy].[sepal_surface]), [Expr1013]=SUM([#######].[dbo].[#######_iris_copy].[sepal_surface]) ; 3.0 ; 0.0 ; 9.15E-5 ; 103 ; 0.017332148 ; [#######].[dbo].[#######_iris_copy].[variety], [Expr1003], [Expr1004], [Expr1012], [Expr1013] ; ; PLAN_ROW ; 0 ; 1.0 |--Sort(ORDER BY:([#######].[dbo].[#######_iris_copy].[variety] ASC)) ; 1 ; 4 ; 3 ; Sort ; Sort ; ORDER BY:([#######].[dbo].[#######_iris_copy].[variety] ASC) ; ; 150.0 ; 0.011261261 ; 0.0017916466 ; 103 ; 0.01724065 ; [#######].[dbo].[#######_iris_copy].[petal_length], [#######].[dbo].[#######_iris_copy].[petal_width], [#######].[dbo].[#######_iris_copy].[variety], [#######].[dbo].[#######_iris_copy].[sepal_surface] ; ; PLAN_ROW ; 0 ; 1.0 |--Table Scan(OBJECT:([#######].[dbo].[#######_iris_copy])) ; 1 ; 5 ; 4 ; Table Scan ; Table Scan ; OBJECT:([#######].[dbo].[#######_iris_copy]) ; [#######].[dbo].[#######_iris_copy].[petal_length], [#######].[dbo].[#######_iris_copy].[petal_width], [#######].[dbo].[#######_iris_copy].[variety], [#######].[dbo].[#######_iris_copy].[sepal_surface] ; 150.0 ; 0.0038657407 ; 3.22E-4 ; 103 ; 0.004187741 ; [#######].[dbo].[#######_iris_copy].[petal_length], [#######].[dbo].[#######_iris_copy].[petal_width], [#######].[dbo].[#######_iris_copy].[variety], [#######].[dbo].[#######_iris_copy].[sepal_surface] ; ; PLAN_ROW ; 0 ; 1.0 [2020/10/21-10:25:39.658] [FRT-52-FlowRunnable] [INFO] [dku.flow.sql] act.compute_iris_by_variety_NP - Executing statement: [2020/10/21-10:25:39.658] [FRT-52-FlowRunnable] [INFO] [dku.flow.sql] act.compute_iris_by_variety_NP - INSERT INTO "dbo"."#######_iris_by_variety" SELECT "variety" AS "variety", MIN("petal_length") AS "petal_length_min", MAX("petal_width") AS "petal_width_max", AVG("sepal_surface") AS "sepal_surface_avg" FROM ( SELECT "sepal_length" AS "sepal_length", "sepal_width" AS "sepal_width", "petal_length" AS "petal_length", "petal_width" AS "petal_width", "variety" AS "variety", "sepal_surface" AS "sepal_surface" FROM "dbo"."#######_iris_copy" ) "dku__beforegrouping" GROUP BY "variety" [2020/10/21-10:25:39.660] [FRT-52-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_by_variety_NP - Reporting start of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_QUERY","id":"#######","startTime":1603268739660,"sqlQuery":{"connectionUsageId":"#######","connection":"#######","query":" \nINSERT INTO \"dbo\".\"#######_iris_by_variety\" \nSELECT \n \"variety\" AS \"variety\",\n MIN(\"petal_length\") AS \"petal_length_min\",\n MAX(\"petal_width\") AS \"petal_width_max\",\n AVG(\"sepal_surface\") AS \"sepal_surface_avg\"\n FROM (\n SELECT \n \"sepal_length\" AS \"sepal_length\",\n \"sepal_width\" AS \"sepal_width\",\n \"petal_length\" AS \"petal_length\",\n \"petal_width\" AS \"petal_width\",\n \"variety\" AS \"variety\",\n \"sepal_surface\" AS \"sepal_surface\"\n FROM \"dbo\".\"#######_iris_copy\"\n ) \"dku__beforegrouping\"\n GROUP BY \"variety\""}} [2020/10/21-10:25:39.660] [FRT-52-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_by_variety_NP - Reporting start of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_QUERY","id":"#######","startTime":1603268739660,"sqlQuery":{"connectionUsageId":"#######","connection":"#######","query":" \nINSERT INTO \"dbo\".\"#######_iris_by_variety\" \nSELECT \n \"variety\" AS \"variety\",\n MIN(\"petal_length\") AS \"petal_length_min\",\n MAX(\"petal_width\") AS \"petal_width_max\",\n AVG(\"sepal_surface\") AS \"sepal_surface_avg\"\n FROM (\n SELECT \n \"sepal_length\" AS \"sepal_length\",\n \"sepal_width\" AS \"sepal_width\",\n \"petal_length\" AS \"petal_length\",\n \"petal_width\" AS \"petal_width\",\n \"variety\" AS \"variety\",\n \"sepal_surface\" AS \"sepal_surface\"\n FROM \"dbo\".\"#######_iris_copy\"\n ) \"dku__beforegrouping\"\n GROUP BY \"variety\""}} [2020/10/21-10:25:39.669] [FRT-52-FlowRunnable] [INFO] [dku.flow.sql] act.compute_iris_by_variety_NP - Statement done [2020/10/21-10:25:39.669] [FRT-52-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_by_variety_NP - Reporting completion of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_QUERY","id":"#######","startTime":1603268739660,"sqlQuery":{"connectionUsageId":"#######","connection":"#######","query":" \nINSERT INTO \"dbo\".\"#######_iris_by_variety\" \nSELECT \n \"variety\" AS \"variety\",\n MIN(\"petal_length\") AS \"petal_length_min\",\n MAX(\"petal_width\") AS \"petal_width_max\",\n AVG(\"sepal_surface\") AS \"sepal_surface_avg\"\n FROM (\n SELECT \n \"sepal_length\" AS \"sepal_length\",\n \"sepal_width\" AS \"sepal_width\",\n \"petal_length\" AS \"petal_length\",\n \"petal_width\" AS \"petal_width\",\n \"variety\" AS \"variety\",\n \"sepal_surface\" AS \"sepal_surface\"\n FROM \"dbo\".\"#######_iris_copy\"\n ) \"dku__beforegrouping\"\n GROUP BY \"variety\""}} [2020/10/21-10:25:39.669] [FRT-52-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_by_variety_NP - Reporting completion of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_QUERY","id":"#######","startTime":1603268739660,"endTime":1603268739669,"sqlQuery":{"connectionUsageId":"#######","connection":"#######","query":" \nINSERT INTO \"dbo\".\"#######_iris_by_variety\" \nSELECT \n \"variety\" AS \"variety\",\n MIN(\"petal_length\") AS \"petal_length_min\",\n MAX(\"petal_width\") AS \"petal_width_max\",\n AVG(\"sepal_surface\") AS \"sepal_surface_avg\"\n FROM (\n SELECT \n \"sepal_length\" AS \"sepal_length\",\n \"sepal_width\" AS \"sepal_width\",\n \"petal_length\" AS \"petal_length\",\n \"petal_width\" AS \"petal_width\",\n \"variety\" AS \"variety\",\n \"sepal_surface\" AS \"sepal_surface\"\n FROM \"dbo\".\"#######_iris_copy\"\n ) \"dku__beforegrouping\"\n GROUP BY \"variety\""}} [2020/10/21-10:25:39.670] [FRT-52-FlowRunnable] [DEBUG] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Commit conn=#######-EEa3lNe [2020/10/21-10:25:39.671] [FRT-52-FlowRunnable] [DEBUG] [dku.connections.sql.provider] act.compute_iris_by_variety_NP - Close conn=#######-EEa3lNe [2020/10/21-10:25:39.672] [FRT-52-FlowRunnable] [INFO] [dku.resourceusage] act.compute_iris_by_variety_NP - Reporting completion of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_CONNECTION","id":"#######","startTime":1603268739597,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:39.672] [FRT-52-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_iris_by_variety_NP - Reporting completion of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_iris_by_variety_NP","activityType":"recipe","recipeType":"grouping","recipeName":"compute_iris_by_variety"},"type":"SQL_CONNECTION","id":"#######","startTime":1603268739597,"endTime":1603268739672,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:39.672] [FRT-52-FlowRunnable] [INFO] [dku.flow.activity] act.compute_iris_by_variety_NP - Run thread done for activity compute_iris_by_variety_NP [2020/10/21-10:25:39.688] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - activity is finished [2020/10/21-10:25:39.689] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Executing default post-activity lifecycle hook [2020/10/21-10:25:39.690] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Activity successful, computing metrics and running checks [2020/10/21-10:25:39.733] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,732 29810 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:39.734] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,732 29810 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:39.734] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,733 29810 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:39.739] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,738 29810 INFO Allowed group ids: [50003] [2020/10/21-10:25:39.746] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,745 29810 INFO User ####### belongs to groups: [503869135, 50003] [2020/10/21-10:25:39.748] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,747 29810 INFO User ####### belongs to group 50003 (dataiku_python_runner) -> allowed [2020/10/21-10:25:39.748] [null-err-55] [INFO] [dku.utils] - 2020-10-21 10:25:39,747 29810 INFO Executing chown -Rh: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### -> ####### [2020/10/21-10:25:39.749] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Activity checks produced 0 values [2020/10/21-10:25:39.750] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Activity is successful, computing timestamps to propagate [2020/10/21-10:25:39.753] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Activity is successful, propagating 3 timestamps [2020/10/21-10:25:39.753] [ActivityExecutor-29] [INFO] [dku.timestamps.sql] running compute_iris_by_variety_NP - Starting to propagate 3 hashes [2020/10/21-10:25:39.769] [ActivityExecutor-29] [DEBUG] [dku.connections.sql.provider] running compute_iris_by_variety_NP - Commit conn=dssdb-h2-flow_state-QkH5bAw [2020/10/21-10:25:39.771] [ActivityExecutor-29] [INFO] [dku.timestamps.sql] running compute_iris_by_variety_NP - Hashes propagated in 18 ms [2020/10/21-10:25:39.774] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Removing samples for #######.iris_by_variety [2020/10/21-10:25:39.774] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_iris_by_variety_NP - Done post-activity tasks [2020/10/21-10:25:39.791] [Thread-41] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:39.795] [FRT-53-FlowRunnable] [DEBUG] [dku.security.fsacl] act.compute_#######_NP - exec setfacl: sudo -n /etc/dataiku-security/#######/execwrapper.sh acls setfacl --path /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### --perm u::rwx --perm g::--- --perm o:--- --perm d:u:dataiku:rwx --perm u:dataiku:rwx --recursive [2020/10/21-10:25:40.017] [null-err-58] [INFO] [dku.utils] - 2020-10-21 10:25:40,017 29820 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:40.019] [null-err-58] [INFO] [dku.utils] - 2020-10-21 10:25:40,018 29820 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:40.020] [null-err-58] [INFO] [dku.utils] - 2020-10-21 10:25:40,018 29820 INFO Executing: ['setfacl', '-RP', '-m', 'u::rwx,g::---,o:---,d:u:dataiku:rwx,u:dataiku:rwx', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######'] [2020/10/21-10:25:40.071] [Thread-44] [INFO] [dku.utils] - Done waiting for return value, got 0 [2020/10/21-10:25:40.090] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Written config to /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/config.json [2020/10/21-10:25:40.091] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Starting wrapper: ["sudo","-n","/etc/dataiku-security/#######/execwrapper.sh","execute","/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/config.json"] [2020/10/21-10:25:40.213] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Reading pipes from wrapper [2020/10/21-10:25:40.294] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,293 29826 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:40.297] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,296 29826 INFO Allowed group ids: [50003] [2020/10/21-10:25:40.305] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,304 29826 INFO User ####### belongs to groups: [503869135, 50003] [2020/10/21-10:25:40.307] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,306 29826 INFO User ####### belongs to group 50003 (dataiku_python_runner) -> allowed [2020/10/21-10:25:40.307] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,306 29826 INFO Reading security conf from /etc/dataiku-security/####### [2020/10/21-10:25:40.308] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,307 29826 INFO Allowed path: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/####### in /appl/dataiku/dss_data [2020/10/21-10:25:40.308] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,307 29826 INFO [BF] Setting up process environment [2020/10/21-10:25:40.308] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,308 29826 INFO [BF] Writing wrapper pipes and pid to wrapper stdout [2020/10/21-10:25:40.310] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Pipes read as bytes: 751 [2020/10/21-10:25:40.311] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Pipes read as bytes: {"pipes": {"stdin": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdin.cib4ecw3", "stderr": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stderr.cib4ecw3", "stdout": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdout.cib4ecw3"}, "pid": 29826, "childPidFile": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/child.pid"} [2020/10/21-10:25:40.311] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Pid read: 29826 [2020/10/21-10:25:40.311] [FRT-53-FlowRunnable] [INFO] [dku.security.process] act.compute_#######_NP - Pipes read: { "stdin": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdin.cib4ecw3", "stderr": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stderr.cib4ecw3", "stdout": "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdout.cib4ecw3" } [2020/10/21-10:25:40.313] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,309 29826 INFO [Parent] Started process 29828 [2020/10/21-10:25:40.321] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,313 29828 INFO [Child] pgroup is set [2020/10/21-10:25:40.321] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,314 29828 INFO [Child] opening stdin pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdin.cib4ecw3 [2020/10/21-10:25:40.322] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,314 29828 INFO [Child] opened stdin pipe [2020/10/21-10:25:40.322] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,315 29828 INFO [Child] opening stdout pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stdout.cib4ecw3 [2020/10/21-10:25:40.322] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,316 29828 INFO [Child] opened stdout [2020/10/21-10:25:40.323] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:40,316 29828 INFO [Child] opening stderr pipe: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/.stderr.cib4ecw3 [2020/10/21-10:25:40.318] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Process reads from nothing [2020/10/21-10:25:40.324] [FRT-53-FlowRunnable] [INFO] [dku.resourceusage] act.compute_#######_NP - Reporting start of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_#######_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_#######"},"type":"LOCAL_PROCESS","id":"j7WJaF4y9kelCJau","startTime":1603268740324,"localProcess":{"cpuCurrent":0.0}} [2020/10/21-10:25:40.325] [FRT-53-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_#######_NP - Reporting start of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_#######_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_#######"},"type":"LOCAL_PROCESS","id":"j7WJaF4y9kelCJau","startTime":1603268740324,"localProcess":{"cpuCurrent":0.0}} [2020/10/21-10:25:40.324] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,316 29828 INFO [Child] opened stderr [2020/10/21-10:25:40.326] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,316 29828 INFO [Child] about to close other fd [2020/10/21-10:25:40.326] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,316 29828 INFO [Child] closed other fd [2020/10/21-10:25:40.326] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,317 29828 INFO [Child] chdired [2020/10/21-10:25:40.327] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,317 29828 INFO setting username=####### uid=503869135 gid=503869135 [2020/10/21-10:25:40.327] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,319 29828 INFO [Child] dropped privileges [2020/10/21-10:25:40.327] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,319 29828 INFO [Child] Checking access to DKUINSTALLDIR and DIP_HOME directories [2020/10/21-10:25:40.328] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,320 29828 INFO [Child] Executing: /appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python : /appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python -u /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/python-exec-wrapper.py /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/script.py [2020/10/21-10:25:40.346] [process-resource-monitor-unkpid-63] [INFO] [dku.security.process] - GET PID CPF=/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/child.pid [2020/10/21-10:25:40.351] [process-resource-monitor-29828-63] [INFO] [dku.usage.computeresource.jek] - Reporting update of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_#######_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_#######"},"type":"LOCAL_PROCESS","id":"j7WJaF4y9kelCJau","startTime":1603268740324,"localProcess":{"pid":29828,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":121,"vmRSSMB":4,"vmHWMMB":4,"vmRSSAnonMB":1,"vmDataMB":1,"vmSizePeakMB":121,"vmRSSPeakMB":4,"vmRSSTotalMBS":0,"majorFaults":0,"childrenMajorFaults":0}} [2020/10/21-10:25:40.351] [process-resource-monitor-29828-63] [DEBUG] [dku.resource] - Process stats for pid 29828: {"pid":29828,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python","cpuUserTimeMS":0,"cpuSystemTimeMS":0,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":0,"cpuCurrent":0.0,"vmSizeMB":121,"vmRSSMB":4,"vmHWMMB":4,"vmRSSAnonMB":1,"vmDataMB":1,"vmSizePeakMB":121,"vmRSSPeakMB":4,"vmRSSTotalMBS":0,"majorFaults":0,"childrenMajorFaults":0} [2020/10/21-10:25:40.462] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO -------------------- [2020/10/21-10:25:40.463] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO Dataiku Python entrypoint starting up [2020/10/21-10:25:40.463] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO executable = /appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python [2020/10/21-10:25:40.463] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO argv = ['/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/python-exec-wrapper.py', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/script.py'] [2020/10/21-10:25:40.464] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO -------------------- [2020/10/21-10:25:40.464] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO Looking for RemoteRunEnvDef in ./remote-run-env-def.json [2020/10/21-10:25:40.464] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,461 INFO Found RemoteRunEnvDef environment: ./remote-run-env-def.json [2020/10/21-10:25:40.474] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,468 INFO Running a DSS Python recipe locally, uinsetting env [2020/10/21-10:25:40.474] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,469 INFO Setup complete, ready to execute Python code [2020/10/21-10:25:40.475] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,469 INFO Sys path: ['/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######', '/appl/dataiku/dss_data/lib/python', '/appl/dataiku/dataiku-dss-8.0.2/python', '/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib64/python36.zip', '/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib64/python3.6', '/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib64/python3.6/lib-dynload', '/opt/rh/rh-python36/root/usr/lib64/python3.6', '/opt/rh/rh-python36/root/usr/lib/python3.6', '/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages', '/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/project-python-libs/#######/python'] [2020/10/21-10:25:40.475] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:40,469 INFO Script file: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/script.py [2020/10/21-10:25:42.766] [Thread-13] [INFO] [dku.job.slave] - Sending status update [2020/10/21-10:25:42.780] [Thread-13] [INFO] [dku.job.slave] - Status update sent [2020/10/21-10:25:44.674] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:44,673 INFO generated new fontManager [2020/10/21-10:25:45.345] [qtp1906029492-19] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:45.345] [qtp1906029492-19] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/get-schema [2020/10/21-10:25:45.346] [qtp1906029492-19] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_SCHEMA::#######.iris_copy [2020/10/21-10:25:45.364] [qtp1906029492-19] [INFO] [dku.job.slave] - Reading schema of dataset #######.iris_copy [2020/10/21-10:25:45.365] [qtp1906029492-19] [DEBUG] [dku.jobs] - Command /tintercom/datasets/get-schema processed in 20ms [2020/10/21-10:25:45.371] [qtp1906029492-20] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:45.371] [qtp1906029492-20] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/read-data [2020/10/21-10:25:45.371] [qtp1906029492-20] [INFO] [dku.job.slave] - Using cached grant: datasetread::READ_DATA::#######.iris_copy [2020/10/21-10:25:45.372] [qtp1906029492-20] [INFO] [dku.input.push] - Using ordering from dataset: {"enabled":false,"rules":[]} [2020/10/21-10:25:45.373] [qtp1906029492-20] [INFO] [dku.input.push] - USTP: push selection.method=FULL records=-1 ratio=0.02 col=null [2020/10/21-10:25:45.373] [qtp1906029492-20] [INFO] [dku.datasets.push] - Push row splits limit= {"maxBytes":-1,"maxRecords":-1,"ordering":{"enabled":false,"rules":[]}} [2020/10/21-10:25:45.374] [qtp1906029492-20] [INFO] [dku.input.rows] - Starting to push split com.dataiku.dip.datasets.sql.AbstractSQLTableDatasetHandler$TableClauseSplit@1eac58f8 with limit= -1 [2020/10/21-10:25:45.375] [qtp1906029492-20] [INFO] [dip.connections.sqlserver] - Log using kerberos, as MSSQLSvc/#######.####### (proxy=%{dssUserLogin}) [2020/10/21-10:25:45.376] [qtp1906029492-20] [INFO] [dku.connections.sql.provider] - Connecting to jdbc:sqlserver://#######.####### with props: {"integratedSecurity":"true","instanceName":"DEINSTANCE00","authenticationScheme":"JavaKerberos","portNumber":"1433","databaseName":"#######"} conn=#######-s7M0Vzb [2020/10/21-10:25:45.376] [qtp1906029492-20] [DEBUG] [dku.connections.sql.driver] - Driver version 7.2 [2020/10/21-10:25:45.376] [qtp1906029492-20] [INFO] [dip.krb.login] - Retrieving impersonated Kerberos credentials for ####### [2020/10/21-10:25:45.419] [qtp1906029492-20] [INFO] [dku.connections.sql.provider] - Driver: Microsoft JDBC Driver 7.2 for SQL Server (JDBC 4.2) 7.2.2.0 (7.2) [2020/10/21-10:25:45.419] [qtp1906029492-20] [INFO] [dku.connections.sql.provider] - Database: Microsoft SQL Server 13.00.5698 (13.0) rowSize=8060 stmts=0 [2020/10/21-10:25:45.421] [qtp1906029492-20] [INFO] [dku.resourceusage] - Reporting start of CRU:{"type":"SQL_CONNECTION","id":"#######","startTime":1603268745419,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:45.421] [qtp1906029492-20] [INFO] [dku.usage.computeresource.jek] - Reporting start of resource usage: {"type":"SQL_CONNECTION","id":"#######","startTime":1603268745419,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:45.422] [qtp1906029492-20] [INFO] [dku.datasets.sql] - Executing query SELECT * FROM "dbo"."#######_iris_copy" (st=SQLServerStatement:8) [2020/10/21-10:25:45.429] [qtp1906029492-20] [INFO] [dku.datasets.sql] - Done executing query (st=SQLServerStatement:8) [2020/10/21-10:25:45.479] [qtp1906029492-20] [INFO] [dku.datasets.sql] - Done iterating result set, returned 150 rows [2020/10/21-10:25:45.485] [qtp1906029492-20] [INFO] [dku.datasets.sql] - Exited push [2020/10/21-10:25:45.485] [qtp1906029492-20] [DEBUG] [dku.connections.sql.provider] - Rollback and close conn=#######-s7M0Vzb [2020/10/21-10:25:45.486] [qtp1906029492-20] [DEBUG] [dku.connections.sql.provider] - Rollback conn=#######-s7M0Vzb [2020/10/21-10:25:45.487] [qtp1906029492-20] [DEBUG] [dku.connections.sql.provider] - Close conn=#######-s7M0Vzb [2020/10/21-10:25:45.487] [qtp1906029492-20] [DEBUG] [dku.connections.sql.provider] - Close conn=#######-s7M0Vzb [2020/10/21-10:25:45.487] [qtp1906029492-20] [INFO] [dku.resourceusage] - Reporting completion of CRU:{"type":"SQL_CONNECTION","id":"#######","startTime":1603268745419,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:45.487] [qtp1906029492-20] [INFO] [dku.usage.computeresource.jek] - Reporting completion of resource usage: {"type":"SQL_CONNECTION","id":"#######","startTime":1603268745419,"endTime":1603268745487,"sqlConnection":{"connection":"#######"}} [2020/10/21-10:25:45.488] [qtp1906029492-20] [DEBUG] [dku.jobs] - Command /tintercom/datasets/read-data processed in 117ms [2020/10/21-10:25:45.505] [qtp1906029492-24] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:45.505] [qtp1906029492-24] [DEBUG] [dku.jobs] - Received command : /tintercom/managed-folders/get-info [2020/10/21-10:25:45.506] [qtp1906029492-24] [INFO] [dku.job.slave] - Trying to obtain grant: project::READ_CONF::####### [2020/10/21-10:25:45.514] [qtp1906029492-24] [INFO] [dku.job.slave] - Getting infos for managed folder####### in ####### [2020/10/21-10:25:45.517] [qtp1906029492-24] [INFO] [dku.managedfolders.handler] - Create provider for #######.####### with path #######/####### [2020/10/21-10:25:45.518] [qtp1906029492-24] [DEBUG] [dku.jobs] - Command /tintercom/managed-folders/get-info processed in 13ms [2020/10/21-10:25:45.524] [qtp1906029492-21] [INFO] [dku.jobs] - Connects using API ticket [2020/10/21-10:25:45.524] [qtp1906029492-21] [DEBUG] [dku.jobs] - Received command : /tintercom/managed-folders/ensure-direct-access [2020/10/21-10:25:45.525] [qtp1906029492-21] [INFO] [dku.job.slave] - Using cached grant: project::READ_CONF::####### [2020/10/21-10:25:45.525] [qtp1906029492-21] [INFO] [dku.job.slave] - Getting access for managed folder####### in ####### [2020/10/21-10:25:45.526] [qtp1906029492-21] [INFO] [dku.managedfolders.handler] - Create provider for #######.####### with path #######/####### [2020/10/21-10:25:45.526] [qtp1906029492-21] [DEBUG] [dku.jobs] - Command /tintercom/managed-folders/ensure-direct-access processed in 2ms [2020/10/21-10:25:46.944] [null-err-62] [INFO] [dku.utils] - *************** Recipe code failed ************** [2020/10/21-10:25:46.944] [null-err-62] [INFO] [dku.utils] - Begin Python stack [2020/10/21-10:25:46.958] [null-err-62] [INFO] [dku.utils] - Traceback (most recent call last): [2020/10/21-10:25:46.958] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/python-exec-wrapper.py", line 206, in [2020/10/21-10:25:46.958] [null-err-62] [INFO] [dku.utils] - exec(f.read()) [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - File "", line 36, in [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/seaborn/axisgrid.py", line 36, in savefig [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - self.fig.savefig(*args, **kwargs) [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/matplotlib/figure.py", line 2203, in savefig [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - self.canvas.print_figure(fname, **kwargs) [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/matplotlib/backend_bases.py", line 2105, in print_figure [2020/10/21-10:25:46.959] [null-err-62] [INFO] [dku.utils] - **kwargs) [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/matplotlib/backends/backend_agg.py", line 535, in print_png [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - with cbook.open_file_cm(filename_or_obj, "wb") as fh: [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - File "/opt/rh/rh-python36/root/usr/lib64/python3.6/contextlib.py", line 81, in __enter__ [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - return next(self.gen) [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/matplotlib/cbook/__init__.py", line 418, in open_file_cm [2020/10/21-10:25:46.960] [null-err-62] [INFO] [dku.utils] - fh, opened = to_filehandle(path_or_file, mode, True, encoding) [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - File "/appl/dataiku/dss_data/code-envs/python/Py36-Admin/lib/python3.6/site-packages/matplotlib/cbook/__init__.py", line 403, in to_filehandle [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - fh = open(fname, flag, encoding=encoding) [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - PermissionError: [Errno 13] Permission denied: '/appl/dataiku/dss_data/#######/iris_scatter.png' [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - End Python stack [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:46,956 INFO Check if spark is available [2020/10/21-10:25:46.961] [null-err-62] [INFO] [dku.utils] - 2020-10-21 10:25:46,957 INFO Not stopping a spark context: No module named 'pyspark' [2020/10/21-10:25:47.221] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:47,221 29826 INFO [Child] Process 29828 exited with exit=1 signal=0 [2020/10/21-10:25:47.222] [wrapper-stderr-60] [INFO] [dku.utils] - 2020-10-21 10:25:47,221 29826 INFO Full child code: 1 [2020/10/21-10:25:47.230] [FRT-53-FlowRunnable] [WARN] [dku.resource] act.compute_#######_NP - stat file for pid 29828 does not exist. Process died? [2020/10/21-10:25:47.231] [FRT-53-FlowRunnable] [INFO] [dku.resourceusage] act.compute_#######_NP - Reporting completion of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_#######_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_#######"},"type":"LOCAL_PROCESS","id":"j7WJaF4y9kelCJau","startTime":1603268740324,"localProcess":{"pid":29828,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python","cpuUserTimeMS":2650,"cpuSystemTimeMS":410,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":10,"cpuTotalMS":3070,"cpuCurrent":0.6113886113886113,"vmSizeMB":805,"vmRSSMB":111,"vmHWMMB":111,"vmRSSAnonMB":91,"vmDataMB":193,"vmSizePeakMB":805,"vmRSSPeakMB":111,"vmRSSTotalMBS":555,"majorFaults":152,"childrenMajorFaults":5}} [2020/10/21-10:25:47.231] [FRT-53-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_#######_NP - Reporting completion of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"#######","projectKey":"#######","jobId":"Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407","activityId":"compute_#######_NP","activityType":"recipe","recipeType":"python","recipeName":"compute_#######"},"type":"LOCAL_PROCESS","id":"j7WJaF4y9kelCJau","startTime":1603268740324,"endTime":1603268747231,"localProcess":{"pid":29828,"commandName":"/appl/dataiku/dss_data/code-envs/python/Py36-Admin/bin/python","cpuUserTimeMS":2650,"cpuSystemTimeMS":410,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":10,"cpuTotalMS":3070,"cpuCurrent":0.6113886113886113,"vmSizeMB":805,"vmRSSMB":111,"vmHWMMB":111,"vmRSSAnonMB":91,"vmDataMB":193,"vmSizePeakMB":805,"vmRSSPeakMB":111,"vmRSSTotalMBS":555,"majorFaults":152,"childrenMajorFaults":5}} [2020/10/21-10:25:47.231] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Error file found, trying to throw it: /appl/dataiku/dss_data/jobs/#######/Build_iris_plots__iris_by_variety_2020-10-21T08-24-49.407/compute_#######_NP/python-recipe/#######/error.json [2020/10/21-10:25:47.232] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Raw error is{"errorType":"\u003cclass \u0027PermissionError\u0027\u003e","message":"[Errno 13] Permission denied: \u0027/appl/dataiku/dss_data/#######/iris_scatter.png\u0027","detailedMessage":"At line 36: \u003cclass \u0027PermissionError\u0027\u003e: [Errno 13] Permission denied: \u0027/appl/dataiku/dss_data/#######/iris_scatter.png\u0027","stackTrace":[]} [2020/10/21-10:25:47.232] [FRT-53-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_#######_NP - Now err: {"errorType":"\u003cclass \u0027PermissionError\u0027\u003e","message":"Error in Python process: [Errno 13] Permission denied: \u0027/appl/dataiku/dss_data/#######/iris_scatter.png\u0027","detailedMessage":"Error in Python process: At line 36: \u003cclass \u0027PermissionError\u0027\u003e: [Errno 13] Permission denied: \u0027/appl/dataiku/dss_data/#######/iris_scatter.png\u0027","stackTrace":[]} [2020/10/21-10:25:47.233] [FRT-53-FlowRunnable] [INFO] [dku.flow.activity] act.compute_#######_NP - Run thread failed for activity compute_#######_NP com.dataiku.common.server.APIError$SerializedErrorException: Error in Python process: At line 36: : [Errno 13] Permission denied: '/appl/dataiku/dss_data/#######/iris_scatter.png' at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.handleErrorFile(AbstractCodeBasedActivityRunner.java:221) at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.handleExecutionResult(AbstractCodeBasedActivityRunner.java:186) at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.execute(AbstractCodeBasedActivityRunner.java:103) at com.dataiku.dip.dataflow.exec.AbstractPythonRecipeRunner.executeScript(AbstractPythonRecipeRunner.java:48) at com.dataiku.dip.recipes.code.python.PythonRecipeRunner.run(PythonRecipeRunner.java:58) at com.dataiku.dip.dataflow.jobrunner.ActivityRunner$FlowRunnableThread.run(ActivityRunner.java:374) [2020/10/21-10:25:47.308] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - activity is finished [2020/10/21-10:25:47.309] [ActivityExecutor-28] [ERROR] [dku.flow.activity] running compute_#######_NP - Activity failed com.dataiku.common.server.APIError$SerializedErrorException: Error in Python process: At line 36: : [Errno 13] Permission denied: '/appl/dataiku/dss_data/#######/iris_scatter.png' at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.handleErrorFile(AbstractCodeBasedActivityRunner.java:221) at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.handleExecutionResult(AbstractCodeBasedActivityRunner.java:186) at com.dataiku.dip.dataflow.exec.AbstractCodeBasedActivityRunner.execute(AbstractCodeBasedActivityRunner.java:103) at com.dataiku.dip.dataflow.exec.AbstractPythonRecipeRunner.executeScript(AbstractPythonRecipeRunner.java:48) at com.dataiku.dip.recipes.code.python.PythonRecipeRunner.run(PythonRecipeRunner.java:58) at com.dataiku.dip.dataflow.jobrunner.ActivityRunner$FlowRunnableThread.run(ActivityRunner.java:374) [2020/10/21-10:25:47.309] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - Executing default post-activity lifecycle hook [2020/10/21-10:25:47.310] [ActivityExecutor-28] [INFO] [dku.flow.activity] running compute_#######_NP - Done post-activity tasks [2020/10/21-10:25:47.327] [ActivityExecutor-28] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/10/21-10:25:47.780] [Thread-13] [INFO] [dku.job.slave] - Sending status update [2020/10/21-10:25:47.782] [ActivityExecutor-32] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/10/21-10:25:47.782] [ActivityExecutor-30] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/10/21-10:25:47.783] [ActivityExecutor-31] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/10/21-10:25:47.788] [Thread-13] [INFO] [dku.job.slave] - Status update sent [2020/10/21-10:25:47.806] [ActivityExecutor-29] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/10/21-10:25:47.807] [qtp1906029492-22] [INFO] [dku.flow.jobrunner] - All activity executor threads joined, end of job [2020/10/21-10:25:47.807] [qtp1906029492-22] [INFO] [dku.flow.jobrunner] - JOB IS COMPLETE [2020/10/21-10:25:47.809] [qtp1906029492-22] [DEBUG] [dku.jobs] - Command /pintercom/run_fully processed in 15128ms [2020/10/21-10:25:47.827] [qtp1906029492-23] [INFO] [dku.jobs] - Connects using Shared secret [2020/10/21-10:25:47.827] [qtp1906029492-23] [DEBUG] [dku.jobs] - Received command : /pintercom/stop_session [2020/10/21-10:25:47.833] [qtp1906029492-23] [DEBUG] [dku.jobs] - Command /pintercom/stop_session processed in 6ms