Oops: an unexpected error occurred Error in Python process: At line 172: : need more than 0 values to unpack Please see our options for getting help HTTP code: , type: ---------------------------------------- DSS startup: jek version:8.0.0 DSS home: /home/dataiku/dss OS: Linux 3.10.0-1127.13.1.el7.x86_64 amd64 - Java: Oracle Corporation 1.8.0_252 [2020/08/24-11:21:07.853] [qtp641449963-21] [INFO] [dku.jobs] - Connects using Shared secret [2020/08/24-11:21:07.853] [qtp641449963-21] [DEBUG] [dku.jobs] - Received command : /pintercom/start_session [2020/08/24-11:21:07.943] [qtp641449963-21] [INFO] [dku.jobs] - Start Session: {"jobProjectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","jobTicketSecret":"6eEaWjdAAg2jf120Mj2llN5Vqf18HKp1X11h8pSa0H3QOJksNPmop7p5Ny3S9VZj","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":"admin","userGroups":["administrators"],"userProfile":"DESIGNER"}} [2020/08/24-11:21:07.996] [qtp641449963-21] [INFO] [dip.tickets.fixed] - Creating service for single API ticket in auth context: admin [2020/08/24-11:21:08.071] [qtp641449963-21] [DEBUG] [dku.jobs] - Command /pintercom/start_session processed in 218ms [2020/08/24-11:21:08.175] [qtp641449963-22] [INFO] [dku.jobs] - Connects using Shared secret [2020/08/24-11:21:08.183] [qtp641449963-22] [DEBUG] [dku.jobs] - Received command : /pintercom/resolve_job [2020/08/24-11:21:08.183] [qtp641449963-22] [INFO] [dku.job.slave] - Starting to resolve job [2020/08/24-11:21:08.669] [qtp641449963-22] [INFO] [dku.job.slave] - { "type": "NON_RECURSIVE_FORCED_BUILD", "projectKey": "DKU_CHURN", "id": "Build_geo_encoded_2020-08-24T11-21-07.571", "name": "Build geo_encoded", "initiator": "admin", "triggeredFrom": "RECIPE", "recipe": "compute_geo_encoded", "initiationTimestamp": 1598268067571, "mailNotification": false, "outputs": [ { "type": "DATASET", "targetDatasetProjectKey": "DKU_CHURN", "targetDataset": "geo_encoded" } ], "refreshHiveMetastore": true } [2020/08/24-11:21:08.669] [qtp641449963-22] [INFO] [dku.job.slave] - Loading recipes [2020/08/24-11:21:08.717] [qtp641449963-22] [DEBUG] [dku.flow.recipes] - Building global graph [2020/08/24-11:21:09.551] [qtp641449963-22] [DEBUG] [dku.flow.recipes] - Done getting global graph t=833ms [2020/08/24-11:21:09.552] [qtp641449963-22] [INFO] [dku.job.slave] - Recipes loaded, computing job details [2020/08/24-11:21:09.590] [qtp641449963-22] [INFO] [dku.flow.compute] - Job output type: DATASET [2020/08/24-11:21:09.642] [qtp641449963-22] [INFO] [dku.flow.compute] - computing job from target DKU_CHURN.geo_encoded partition NP [2020/08/24-11:21:09.666] [qtp641449963-22] [INFO] [dku.flow.compute] - Refreshing DKU_CHURN.geo_encoded/NP with recipe compute_geo_encoded [2020/08/24-11:21:09.729] [qtp641449963-22] [INFO] [dku.flow.compute.op] activity compute_geo_encoded_ - Compute output partitions for subgraph, with target : DKU_CHURN.geo_encoded and partition: NP [2020/08/24-11:21:09.730] [qtp641449963-22] [INFO] [dku.flow.compute.op] activity compute_geo_encoded_ - Target DKU_CHURN.geo_encoded is not partitioned [2020/08/24-11:21:09.731] [qtp641449963-22] [INFO] [dku.flow.compute.op] activity compute_geo_encoded_ - Add output partition for DKU_CHURN.geo_encoded : NP [2020/08/24-11:21:09.732] [qtp641449963-22] [INFO] [dku.flow.compute] activity compute_geo_encoded_ - computed output partitions: {DKU_CHURN.geo_encoded=} [2020/08/24-11:21:09.770] [qtp641449963-22] [INFO] [dku.flow.compute.ip] activity compute_geo_encoded_ - 0 dependency for DKU_CHURN.revenue_loss [2020/08/24-11:21:09.770] [qtp641449963-22] [INFO] [dku.flow.compute.ip] activity compute_geo_encoded_ - source DKU_CHURN.revenue_loss is not partitioned, including the global partition [2020/08/24-11:21:09.771] [qtp641449963-22] [INFO] [dku.flow.compute] activity compute_geo_encoded_ - computed input partitions : {DKU_CHURN.revenue_loss=[]} [2020/08/24-11:21:09.793] [qtp641449963-22] [INFO] [dku.flow.compute] - Before prune, job looks like: JOB ACTIVITY ROOT DEPS ACTIVITY compute_geo_encoded_NP SGID: compute_geo_encoded_NP SRC: DKU_CHURN.revenue_loss (partitions: NP) DST: DKU_CHURN.geo_encoded (partition: NP) [2020/08/24-11:21:09.794] [qtp641449963-22] [INFO] [dku.flow.compute] - After cleanup of implicit recipes, job looks like: JOB ACTIVITY ROOT DEPS ACTIVITY compute_geo_encoded_NP SGID: compute_geo_encoded_NP SRC: DKU_CHURN.revenue_loss (partitions: NP) DST: DKU_CHURN.geo_encoded (partition: NP) [2020/08/24-11:21:09.797] [qtp641449963-22] [INFO] [dku.flow.compute] - Job project: DKU_CHURN [2020/08/24-11:21:09.846] [qtp641449963-22] [INFO] [dku.flow.compute] - Doing job pruning according to settings 8287.715: [GC (Allocation Failure) [PSYoungGen: 124915K->9203K(131072K)] 132865K->20453K(163328K), 0.1027859 secs] [Times: user=0.09 sys=0.01, real=0.10 secs] [2020/08/24-11:21:09.974] [qtp641449963-22] [INFO] [dku.flow.compute] - not pruning activity, job type is NON_RECURSIVE_FORCED_BUILD [2020/08/24-11:21:09.975] [qtp641449963-22] [INFO] [dku.flow.compute] - After prune, job looks like that [2020/08/24-11:21:09.976] [qtp641449963-22] [INFO] [dku.flow.compute] - JOB ACTIVITY ROOT DEPS ACTIVITY compute_geo_encoded_NP SGID: compute_geo_encoded_NP SRC: DKU_CHURN.revenue_loss (partitions: NP) DST: DKU_CHURN.geo_encoded (partition: NP) [2020/08/24-11:21:09.976] [qtp641449963-22] [INFO] [dku.flow.compute] - Done building final job graph [2020/08/24-11:21:09.977] [qtp641449963-22] [INFO] [dku.job.slave] - Done computing job data, dumping graph [2020/08/24-11:21:09.977] [qtp641449963-22] [INFO] [dku.job.slave] - JOB ACTIVITY ROOT DEPS ACTIVITY compute_geo_encoded_NP SGID: compute_geo_encoded_NP SRC: DKU_CHURN.revenue_loss (partitions: NP) DST: DKU_CHURN.geo_encoded (partition: NP) [2020/08/24-11:21:09.980] [qtp641449963-22] [INFO] [dku.job.slave] - Job has the following sources: [{"projectKey":"DKU_CHURN","type":"DATASET","id":"revenue_loss"}] [2020/08/24-11:21:10.004] [qtp641449963-22] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_DATA::DKU_CHURN.revenue_loss [2020/08/24-11:21:10.088] [qtp641449963-22] [DEBUG] [dku.jobs] - Command /pintercom/resolve_job processed in 1913ms [2020/08/24-11:21:10.119] [qtp641449963-23] [INFO] [dku.jobs] - Connects using Shared secret [2020/08/24-11:21:10.120] [qtp641449963-23] [DEBUG] [dku.jobs] - Received command : /pintercom/run_fully [2020/08/24-11:21:10.171] [qtp641449963-23] [INFO] [dku.job.slave] - Job run started in kernel with pid 2050 [2020/08/24-11:21:10.206] [qtp641449963-23] [INFO] [dku.flow.jobrunner] - Creating 5 activity runner thread(s). [2020/08/24-11:21:10.221] [qtp641449963-23] [INFO] [dku.flow.jobrunner] - Starting activity executor threads [2020/08/24-11:21:10.320] [qtp641449963-23] [INFO] [dku.flow.jobrunner] - Waiting for activity executor threads [2020/08/24-11:21:10.351] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] - About to run compute_geo_encoded_NP [2020/08/24-11:21:10.447] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] running compute_geo_encoded_NP - Allocated a slot for this activity! [2020/08/24-11:21:10.449] [ActivityExecutor-29] [INFO] [dku.flow.jobrunner] running compute_geo_encoded_NP - Run activity [2020/08/24-11:21:10.524] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Executing default pre-activity lifecycle hook [2020/08/24-11:21:10.594] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Checking if sources are ready [2020/08/24-11:21:10.679] [ActivityExecutor-29] [DEBUG] [dku.db.internal] running compute_geo_encoded_NP - Created DSSDBConnection dssdb-h2-flow_state-FEKK0OW [2020/08/24-11:21:10.718] [ActivityExecutor-29] [DEBUG] [dku.dataset.hash] running compute_geo_encoded_NP - Readiness cache miss for dataset__admin__DKU_CHURN.revenue_loss__NP [2020/08/24-11:21:10.757] [ActivityExecutor-29] [INFO] [dku.datasets.file] running compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:10.762] [ActivityExecutor-29] [INFO] [dku.datasets.ftplike] running compute_geo_encoded_NP - Enumerating Filesystem dataset prefix= [2020/08/24-11:21:10.816] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumerating local filesystem prefix=/ [2020/08/24-11:21:10.819] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumeration done nb_paths=1 size=140763 [2020/08/24-11:21:10.835] [ActivityExecutor-29] [INFO] [dku.dataset.hash] running compute_geo_encoded_NP - Caching readiness for dataset__admin__DKU_CHURN.revenue_loss__NP s=READY h=laRxnaP0X8GeOCIRP+XEJA [2020/08/24-11:21:10.836] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Checked source readiness DKU_CHURN.revenue_loss -> true [2020/08/24-11:21:10.837] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Computing hashes to propagate BEFORE activity [2020/08/24-11:21:10.846] [ActivityExecutor-29] [DEBUG] [dku.dataset.hash] running compute_geo_encoded_NP - Readiness cache miss for dataset__admin__DKU_CHURN.revenue_loss__NP [2020/08/24-11:21:10.848] [ActivityExecutor-29] [INFO] [dku.datasets.file] running compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:10.879] [ActivityExecutor-29] [INFO] [dku.datasets.ftplike] running compute_geo_encoded_NP - Enumerating Filesystem dataset prefix= [2020/08/24-11:21:10.883] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumerating local filesystem prefix=/ [2020/08/24-11:21:10.885] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumeration done nb_paths=1 size=140763 [2020/08/24-11:21:10.887] [ActivityExecutor-29] [INFO] [dku.dataset.hash] running compute_geo_encoded_NP - Caching readiness for dataset__admin__DKU_CHURN.revenue_loss__NP s=READY h=laRxnaP0X8GeOCIRP+XEJA [2020/08/24-11:21:10.913] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Recorded 1 hashes before activity run [2020/08/24-11:21:10.916] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Building recipe runner of type [2020/08/24-11:21:10.979] [ActivityExecutor-29] [DEBUG] [dku.job.activity] running compute_geo_encoded_NP - Filling source sizes [2020/08/24-11:21:10.986] [ActivityExecutor-29] [INFO] [dku.datasets.file] running compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:11.010] [ActivityExecutor-29] [INFO] [dku.datasets.ftplike] running compute_geo_encoded_NP - Enumerating Filesystem dataset prefix= [2020/08/24-11:21:11.014] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumerating local filesystem prefix=/ [2020/08/24-11:21:11.016] [ActivityExecutor-29] [DEBUG] [dku.fs.local] running compute_geo_encoded_NP - Enumeration done nb_paths=1 size=140763 [2020/08/24-11:21:11.018] [ActivityExecutor-29] [DEBUG] [dku.job.activity] running compute_geo_encoded_NP - Done filling source sizes [2020/08/24-11:21:11.035] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Recipe runner built, will use 1 thread(s) [2020/08/24-11:21:11.037] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Starting execution thread: com.dataiku.dip.recipes.customcode.CustomPythonRecipeRunner@4240067c [2020/08/24-11:21:11.052] [ActivityExecutor-29] [DEBUG] [dku.flow.activity] running compute_geo_encoded_NP - Execution threads started, waiting for activity end [2020/08/24-11:21:11.061] [FRT-34-FlowRunnable] [INFO] [dku.flow.activity] act.compute_geo_encoded_NP - Run thread for activity compute_geo_encoded_NP starting [2020/08/24-11:21:11.075] [FRT-34-FlowRunnable] [INFO] [dku.flow.custompython] act.compute_geo_encoded_NP - Dumping Python script to /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/script.py [2020/08/24-11:21:11.142] [FRT-34-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_geo_encoded_NP - Dumping Python script to /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/script.py [2020/08/24-11:21:11.163] [FRT-34-FlowRunnable] [INFO] [dku.datasets.file] act.compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"DKU_CHURN/geo_encoded","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:11.169] [FRT-34-FlowRunnable] [INFO] [dku.datasets.file] act.compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:11.173] [FRT-34-FlowRunnable] [INFO] [dku.datasets.file] act.compute_geo_encoded_NP - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:11.217] [FRT-34-FlowRunnable] [WARN] [dku.code.projectLibs] act.compute_geo_encoded_NP - External libraries file not found: /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/localconfig/projects/DKU_CHURN/lib/external-libraries.json [2020/08/24-11:21:11.219] [FRT-34-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_geo_encoded_NP - EXTERNAL LIBS FROM DKU_CHURN is {"gitReferences":{},"pythonPath":["python"],"rsrcPath":["R"],"importLibrariesFromProjects":[]} [2020/08/24-11:21:11.236] [FRT-34-FlowRunnable] [INFO] [dku.code.projectLibs] act.compute_geo_encoded_NP - chunkFolder is /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/localconfig/projects/DKU_CHURN/lib/R [2020/08/24-11:21:11.244] [FRT-34-FlowRunnable] [INFO] [dip.plugin.presets] act.compute_geo_encoded_NP - Checking project-level settings for overriden presets and additional presets [2020/08/24-11:21:11.276] [FRT-34-FlowRunnable] [INFO] [xxx] act.compute_geo_encoded_NP - RSRC PATH: ["/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/localconfig/projects/DKU_CHURN/lib/R"] [2020/08/24-11:21:11.278] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Writing dku-exec-env for local execution in /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/remote-run-env-def.json [2020/08/24-11:21:11.304] [FRT-34-FlowRunnable] [INFO] [dku.code.envs.resolution] act.compute_geo_encoded_NP - Executing Python activity in env: plugin_geocoder_managed [2020/08/24-11:21:11.327] [FRT-34-FlowRunnable] [INFO] [dku.flow.abstract.python] act.compute_geo_encoded_NP - Execute activity command: ["/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python","-u","/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/python-exec-wrapper.py","/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/script.py"] [2020/08/24-11:21:11.328] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Run command insecurely, from user dataiku [2020/08/24-11:21:11.343] [FRT-34-FlowRunnable] [INFO] [dku.security.process] act.compute_geo_encoded_NP - Starting process (regular) [2020/08/24-11:21:11.367] [FRT-34-FlowRunnable] [INFO] [dku.security.process] act.compute_geo_encoded_NP - Process started with pid=2436 [2020/08/24-11:21:11.372] [FRT-34-FlowRunnable] [INFO] [dku.processes.cgroups] act.compute_geo_encoded_NP - Will use cgroups [] [2020/08/24-11:21:11.372] [FRT-34-FlowRunnable] [INFO] [dku.processes.cgroups] act.compute_geo_encoded_NP - Applying rules to used cgroups: [] [2020/08/24-11:21:11.423] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Process reads from nothing [2020/08/24-11:21:11.428] [FRT-34-FlowRunnable] [INFO] [dku.resourceusage] act.compute_geo_encoded_NP - Reporting start of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"admin","projectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","activityId":"compute_geo_encoded_NP","activityType":"recipe","recipeType":"CustomCode_forward_geocoding","recipeName":"compute_geo_encoded"},"type":"LOCAL_PROCESS","id":"CvdDvQoaRrvchet9","startTime":1598268071424,"localProcess":{"cpuCurrent":0.0}} [2020/08/24-11:21:11.430] [FRT-34-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_geo_encoded_NP - Reporting start of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"admin","projectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","activityId":"compute_geo_encoded_NP","activityType":"recipe","recipeType":"CustomCode_forward_geocoding","recipeName":"compute_geo_encoded"},"type":"LOCAL_PROCESS","id":"CvdDvQoaRrvchet9","startTime":1598268071424,"localProcess":{"cpuCurrent":0.0}} [2020/08/24-11:21:11.542] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,541 INFO -------------------- [2020/08/24-11:21:11.558] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,543 INFO Dataiku Python entrypoint starting up [2020/08/24-11:21:11.559] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,543 INFO executable = /home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python [2020/08/24-11:21:11.560] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,543 INFO argv = ['/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/python-exec-wrapper.py', '/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/script.py'] [2020/08/24-11:21:11.561] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,543 INFO -------------------- [2020/08/24-11:21:11.561] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,544 INFO Looking for RemoteRunEnvDef in ./remote-run-env-def.json [2020/08/24-11:21:11.562] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,544 INFO Found RemoteRunEnvDef environment: ./remote-run-env-def.json [2020/08/24-11:21:11.562] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,545 INFO Running a DSS Python recipe locally, uinsetting env [2020/08/24-11:21:11.563] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,546 INFO Setup complete, ready to execute Python code [2020/08/24-11:21:11.565] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,546 INFO Sys path: ['/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd', '/home/dataiku/dss/lib/python', '/home/dataiku/dataiku-dss-8.0.0/python', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python27.zip', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python2.7', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python2.7/plat-linux2', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python2.7/lib-tk', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python2.7/lib-old', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib64/python2.7/lib-dynload', '/usr/lib64/python2.7', '/usr/lib/python2.7', '/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/lib/python2.7/site-packages', u'/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/localconfig/projects/DKU_CHURN/lib/python', u'/home/dataiku/dss/plugins/installed/geocoder/python-lib'] [2020/08/24-11:21:11.565] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:11,546 INFO Script file: /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/script.py [2020/08/24-11:21:11.537] [process-resource-monitor-2436-39] [INFO] [dku.usage.computeresource.jek] - Reporting update of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"admin","projectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","activityId":"compute_geo_encoded_NP","activityType":"recipe","recipeType":"CustomCode_forward_geocoding","recipeName":"compute_geo_encoded"},"type":"LOCAL_PROCESS","id":"CvdDvQoaRrvchet9","startTime":1598268071424,"localProcess":{"pid":2436,"commandName":"/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python","cpuUserTimeMS":50,"cpuSystemTimeMS":10,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":60,"cpuCurrent":0.0,"vmSizeMB":149,"vmRSSMB":5,"vmHWMMB":5,"vmRSSAnonMB":3,"vmDataMB":3,"vmSizePeakMB":149,"vmRSSPeakMB":5,"vmRSSTotalMBS":0,"majorFaults":0,"childrenMajorFaults":0}} [2020/08/24-11:21:11.571] [process-resource-monitor-2436-39] [DEBUG] [dku.resource] - Process stats for pid 2436: {"pid":2436,"commandName":"/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python","cpuUserTimeMS":50,"cpuSystemTimeMS":10,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":60,"cpuCurrent":0.0,"vmSizeMB":149,"vmRSSMB":5,"vmHWMMB":5,"vmRSSAnonMB":3,"vmDataMB":3,"vmSizePeakMB":149,"vmRSSPeakMB":5,"vmRSSTotalMBS":0,"majorFaults":0,"childrenMajorFaults":0} [2020/08/24-11:21:13.903] [qtp641449963-24] [INFO] [dku.jobs] - Connects using API ticket [2020/08/24-11:21:13.903] [qtp641449963-24] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/get-schema [2020/08/24-11:21:13.917] [qtp641449963-24] [INFO] [dku.job.slave] - Trying to obtain grant: datasetread::READ_SCHEMA::DKU_CHURN.revenue_loss [2020/08/24-11:21:13.950] [qtp641449963-24] [INFO] [dku.job.slave] - Reading schema of dataset DKU_CHURN.revenue_loss [2020/08/24-11:21:13.954] [qtp641449963-24] [DEBUG] [dku.jobs] - Command /tintercom/datasets/get-schema processed in 50ms [2020/08/24-11:21:13.982] [qtp641449963-20] [INFO] [dku.jobs] - Connects using API ticket [2020/08/24-11:21:13.982] [qtp641449963-20] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/read-data [2020/08/24-11:21:13.990] [qtp641449963-20] [INFO] [dku.job.slave] - Using cached grant: datasetread::READ_DATA::DKU_CHURN.revenue_loss [2020/08/24-11:21:14.039] [qtp641449963-20] [INFO] [dku.datasets.file] - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:14.056] [qtp641449963-20] [INFO] [dku.datasets.ftplike] - Enumerating Filesystem dataset prefix= [2020/08/24-11:21:14.059] [qtp641449963-20] [DEBUG] [dku.fs.local] - Enumerating local filesystem prefix=/ [2020/08/24-11:21:14.065] [qtp641449963-20] [DEBUG] [dku.fs.local] - Enumeration done nb_paths=1 size=140763 [2020/08/24-11:21:14.065] [qtp641449963-20] [INFO] [dku.input.push] - USTP: push selection.method=FULL records=-1 ratio=0.02 col=null [2020/08/24-11:21:14.071] [qtp641449963-20] [INFO] [dku.format] - Extractor run: limit={"maxBytes":-1,"maxRecords":-1,"ordering":{"enabled":false,"rules":[]}} totalRecords=0 [2020/08/24-11:21:14.091] [qtp641449963-20] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:14.092] [qtp641449963-20] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:14.092] [qtp641449963-20] [INFO] [dku.format] - Start compressed [GZIP] stream: /home/dataiku/dss/managed_datasets/DKU_CHURN.revenue_loss/out-s0.csv.gz / totalRecsBefore=0 [2020/08/24-11:21:14.092] [qtp641449963-20] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:14.093] [qtp641449963-20] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:15.330] [Thread-13] [INFO] [dku.job.slave] - Sending status update [2020/08/24-11:21:15.366] [Thread-13] [INFO] [dku.job.slave] - Status update sent [2020/08/24-11:21:16.254] [qtp641449963-20] [INFO] [dku.format] - after stream totalComp=140763 totalUncomp=388560 totalRec=1809 [2020/08/24-11:21:16.255] [qtp641449963-20] [INFO] [dku.format] - Extractor run done, totalCompressed=140763 totalRecords=1809 [2020/08/24-11:21:16.256] [qtp641449963-20] [DEBUG] [dku.jobs] - Command /tintercom/datasets/read-data processed in 2274ms [2020/08/24-11:21:16.729] [qtp641449963-22] [INFO] [dku.jobs] - Connects using API ticket [2020/08/24-11:21:16.729] [qtp641449963-22] [DEBUG] [dku.jobs] - Received command : /tintercom/datasets/read-data [2020/08/24-11:21:16.731] [qtp641449963-22] [INFO] [dku.job.slave] - Using cached grant: datasetread::READ_DATA::DKU_CHURN.revenue_loss [2020/08/24-11:21:16.736] [qtp641449963-22] [INFO] [dku.datasets.file] - Building Filesystem handler config: {"connection":"filesystem_managed","path":"/DKU_CHURN.revenue_loss","notReadyIfEmpty":false,"filesSelectionRules":{"mode":"ALL","excludeRules":[],"includeRules":[],"explicitFiles":[]}} [2020/08/24-11:21:16.736] [qtp641449963-22] [INFO] [dku.datasets.ftplike] - Enumerating Filesystem dataset prefix= [2020/08/24-11:21:16.738] [qtp641449963-22] [DEBUG] [dku.fs.local] - Enumerating local filesystem prefix=/ [2020/08/24-11:21:16.738] [qtp641449963-22] [DEBUG] [dku.fs.local] - Enumeration done nb_paths=1 size=140763 [2020/08/24-11:21:16.739] [qtp641449963-22] [INFO] [dku.input.push] - USTP: push selection.method=FULL records=-1 ratio=0.02 col=null [2020/08/24-11:21:16.757] [qtp641449963-22] [INFO] [dku.format] - Extractor run: limit={"maxBytes":-1,"maxRecords":-1,"ordering":{"enabled":false,"rules":[]}} totalRecords=0 [2020/08/24-11:21:16.757] [qtp641449963-22] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:16.758] [qtp641449963-22] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:16.758] [qtp641449963-22] [INFO] [dku.format] - Start compressed [GZIP] stream: /home/dataiku/dss/managed_datasets/DKU_CHURN.revenue_loss/out-s0.csv.gz / totalRecsBefore=0 [2020/08/24-11:21:16.758] [qtp641449963-22] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** [2020/08/24-11:21:16.758] [qtp641449963-22] [INFO] [dku] - getCompression filename=**out-s0.csv.gz** 8294.962: [GC (Metadata GC Threshold) [PSYoungGen: 94161K->2662K(133120K)] 105410K->21652K(165376K), 0.1124880 secs] [Times: user=0.11 sys=0.00, real=0.11 secs] 8295.075: [Full GC (Metadata GC Threshold) [PSYoungGen: 2662K->0K(133120K)] [ParOldGen: 18989K->14573K(51200K)] 21652K->14573K(184320K), [Metaspace: 34903K->34841K(1081344K)], 0.2218808 secs] [Times: user=0.22 sys=0.00, real=0.22 secs] [2020/08/24-11:21:17.894] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:17,886 INFO Starting dataframes iterator [2020/08/24-11:21:18.096] [qtp641449963-22] [INFO] [dku.format] - after stream totalComp=140763 totalUncomp=388560 totalRec=1809 [2020/08/24-11:21:18.133] [qtp641449963-22] [INFO] [dku.format] - Extractor run done, totalCompressed=140763 totalRecords=1809 [2020/08/24-11:21:18.134] [qtp641449963-22] [DEBUG] [dku.jobs] - Command /tintercom/datasets/read-data processed in 1405ms [2020/08/24-11:21:18.953] [null-err-37] [INFO] [dku.utils] - *************** Recipe code failed ************** [2020/08/24-11:21:18.954] [null-err-37] [INFO] [dku.utils] - Begin Python stack [2020/08/24-11:21:18.955] [null-err-37] [INFO] [dku.utils] - Traceback (most recent call last): [2020/08/24-11:21:18.955] [null-err-37] [INFO] [dku.utils] - File "/home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/python-exec-wrapper.py", line 206, in [2020/08/24-11:21:18.956] [null-err-37] [INFO] [dku.utils] - exec(f.read()) [2020/08/24-11:21:18.956] [null-err-37] [INFO] [dku.utils] - File "", line 172, in [2020/08/24-11:21:18.956] [null-err-37] [INFO] [dku.utils] - File "", line 136, in main [2020/08/24-11:21:18.957] [null-err-37] [INFO] [dku.utils] - ValueError: need more than 0 values to unpack [2020/08/24-11:21:18.961] [null-err-37] [INFO] [dku.utils] - End Python stack [2020/08/24-11:21:18.961] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:18,944 INFO Check if spark is available [2020/08/24-11:21:18.962] [null-err-37] [INFO] [dku.utils] - 2020-08-24 11:21:18,944 INFO Not stopping a spark context: No module named pyspark.context [2020/08/24-11:21:19.153] [FRT-34-FlowRunnable] [WARN] [dku.resource] act.compute_geo_encoded_NP - stat file for pid 2436 does not exist. Process died? [2020/08/24-11:21:19.154] [FRT-34-FlowRunnable] [INFO] [dku.resourceusage] act.compute_geo_encoded_NP - Reporting completion of CRU:{"context":{"type":"JOB_ACTIVITY","authIdentifier":"admin","projectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","activityId":"compute_geo_encoded_NP","activityType":"recipe","recipeType":"CustomCode_forward_geocoding","recipeName":"compute_geo_encoded"},"type":"LOCAL_PROCESS","id":"CvdDvQoaRrvchet9","startTime":1598268071424,"localProcess":{"pid":2436,"commandName":"/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python","cpuUserTimeMS":1850,"cpuSystemTimeMS":180,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":2030,"cpuCurrent":0.39071796905989686,"vmSizeMB":413,"vmRSSMB":57,"vmHWMMB":58,"vmRSSAnonMB":45,"vmDataMB":43,"vmSizePeakMB":426,"vmRSSPeakMB":57,"vmRSSTotalMBS":285,"majorFaults":0,"childrenMajorFaults":0}} [2020/08/24-11:21:19.155] [FRT-34-FlowRunnable] [INFO] [dku.usage.computeresource.jek] act.compute_geo_encoded_NP - Reporting completion of resource usage: {"context":{"type":"JOB_ACTIVITY","authIdentifier":"admin","projectKey":"DKU_CHURN","jobId":"Build_geo_encoded_2020-08-24T11-21-07.571","activityId":"compute_geo_encoded_NP","activityType":"recipe","recipeType":"CustomCode_forward_geocoding","recipeName":"compute_geo_encoded"},"type":"LOCAL_PROCESS","id":"CvdDvQoaRrvchet9","startTime":1598268071424,"endTime":1598268079155,"localProcess":{"pid":2436,"commandName":"/home/dataiku/dss/code-envs/python/plugin_geocoder_managed/bin/python","cpuUserTimeMS":1850,"cpuSystemTimeMS":180,"cpuChildrenUserTimeMS":0,"cpuChildrenSystemTimeMS":0,"cpuTotalMS":2030,"cpuCurrent":0.39071796905989686,"vmSizeMB":413,"vmRSSMB":57,"vmHWMMB":58,"vmRSSAnonMB":45,"vmDataMB":43,"vmSizePeakMB":426,"vmRSSPeakMB":57,"vmRSSTotalMBS":285,"majorFaults":0,"childrenMajorFaults":0}} [2020/08/24-11:21:19.156] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Error file found, trying to throw it: /home/dataiku/dss/jobs/DKU_CHURN/Build_geo_encoded_2020-08-24T11-21-07.571/compute_geo_encoded_NP/custom-python-recipe/pyoutSt5Y9DiZgMGd/error.json [2020/08/24-11:21:19.157] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Raw error is{"errorType":"\u003ctype \u0027exceptions.ValueError\u0027\u003e","message":"need more than 0 values to unpack","detailedMessage":"At line 172: \u003ctype \u0027exceptions.ValueError\u0027\u003e: need more than 0 values to unpack","stackTrace":[]} [2020/08/24-11:21:19.158] [FRT-34-FlowRunnable] [INFO] [dku.recipes.code.base] act.compute_geo_encoded_NP - Now err: {"errorType":"\u003ctype \u0027exceptions.ValueError\u0027\u003e","message":"Error in Python process: need more than 0 values to unpack","detailedMessage":"Error in Python process: At line 172: \u003ctype \u0027exceptions.ValueError\u0027\u003e: need more than 0 values to unpack","stackTrace":[]} [2020/08/24-11:21:19.163] [FRT-34-FlowRunnable] [INFO] [dku.flow.activity] act.compute_geo_encoded_NP - Run thread failed for activity compute_geo_encoded_NP com.dataiku.common.server.APIError$SerializedErrorException: Error in Python process: At line 172: : need more than 0 values to unpack 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.customcode.CustomPythonRecipeRunner.run(CustomPythonRecipeRunner.java:71) at com.dataiku.dip.dataflow.jobrunner.ActivityRunner$FlowRunnableThread.run(ActivityRunner.java:374) [2020/08/24-11:21:19.287] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - activity is finished [2020/08/24-11:21:19.288] [ActivityExecutor-29] [ERROR] [dku.flow.activity] running compute_geo_encoded_NP - Activity failed com.dataiku.common.server.APIError$SerializedErrorException: Error in Python process: At line 172: : need more than 0 values to unpack 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.customcode.CustomPythonRecipeRunner.run(CustomPythonRecipeRunner.java:71) at com.dataiku.dip.dataflow.jobrunner.ActivityRunner$FlowRunnableThread.run(ActivityRunner.java:374) [2020/08/24-11:21:19.289] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Executing default post-activity lifecycle hook [2020/08/24-11:21:19.328] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Removing samples for DKU_CHURN.geo_encoded [2020/08/24-11:21:19.332] [ActivityExecutor-29] [INFO] [dku.flow.activity] running compute_geo_encoded_NP - Done post-activity tasks [2020/08/24-11:21:19.492] [ActivityExecutor-33] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/08/24-11:21:19.493] [ActivityExecutor-30] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/08/24-11:21:19.493] [ActivityExecutor-32] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/08/24-11:21:19.494] [ActivityExecutor-31] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/08/24-11:21:19.496] [ActivityExecutor-29] [DEBUG] [dku.flow.jobrunner] - No activity is running, and none is available --> End of ActivityExecutorThread [2020/08/24-11:21:19.497] [qtp641449963-23] [INFO] [dku.flow.jobrunner] - All activity executor threads joined, end of job [2020/08/24-11:21:19.497] [qtp641449963-23] [INFO] [dku.flow.jobrunner] - JOB IS COMPLETE [2020/08/24-11:21:19.503] [qtp641449963-23] [DEBUG] [dku.jobs] - Command /pintercom/run_fully processed in 9383ms [2020/08/24-11:21:19.625] [qtp641449963-19] [INFO] [dku.jobs] - Connects using Shared secret [2020/08/24-11:21:19.625] [qtp641449963-19] [DEBUG] [dku.jobs] - Received command : /pintercom/stop_session [2020/08/24-11:21:19.640] [qtp641449963-19] [DEBUG] [dku.jobs] - Command /pintercom/stop_session processed in 15ms