Docker image digest: sha256:525c91e01875050fbf65cdb4bc83a45744c54f9027fa05f76f88713f3d37f4e3 INFO[2018-09-20T21:49:20Z] Using config: .circleci/config.yml DEBU[2018-09-20T21:49:20Z] local unix path configured path=/tmp/picard060232554/eventprocessor.sock DEBU[2018-09-20T21:49:20Z] config received config_string="{\"TaskId\":\"localbuild-1537480160\",\"TaskInfo\":{\"BuildNum\":\"\",\"BuildURI\":\"\",\"NodeIndex\":0,\"NodeTotal\":1,\"RepositoryURI\":\"git@bitbucket.org:timefinanceiro/alpe-skytef-gw.git\",\"Branch\":\"develop\",\"Revision\":\"a9953b37457f542b54b97ee067f4e35bbb981307\",\"CheckoutKey\":\"\",\"Job\":\"build\",\"SkipCheckout\":true,\"SkipCache\":false,\"SshKeys\":null,\"VcsKnownHostsEntry\":\"\",\"ResourceClassID\":\"\",\"Volumes\":null,\"Environment\":{},\"CircleEnvs\":{},\"Workflow\":{\"WorkflowID\":\"\",\"JobID\":\"\",\"WorkspaceID\":\"\",\"UpstreamJobIDs\":null,\"UpstreamConcurrencyMap\":null},\"Storage\":{\"ProjectRoot\":\"noop://\",\"AccessKey\":\"\",\"SecretKey\":\"\",\"SessionToken\":\"\"},\"TestResults\":null,\"Limits\":{\"StepTimeoutSecs\":21600,\"MaxNoOutputTimeoutSecs\":7200},\"MachineCreatorOpts\":{\"vmServiceUrl\":\"\",\"allocated_docker_socket\":\"/var/run/docker.sock\",\"approximate_docker_image\":\"\"},\"Flags\":{\"all-features-enabled\":true,\"local-build\":true},\"BuildToken\":\"default-token\"},\"PreAuthorizedSshKeys\":[],\"SshEnabled\":false,\"ConfigYml\":\"version: 2\\njobs:\\n build:\\n docker:\\n - image: circleci/python:3.6.6\\n\\n # - image: mongo:2.6.8\\n # command: [mongod, --smallfiles]\\n\\n # - image: postgres:9.4.1\\n # # some containers require setting environment variables\\n # environment:\\n # POSTGRES_USER: root\\n\\n # - image: redis@sha256:54057dd7e125ca41afe526a877e8bd35ec2cdd33b9217e022ed37bdcf7d09673\\n\\n # - image: rabbitmq:3.5.4\\n\\n environment:\\n TEST_REPORTS: /tmp/test-reports\\n\\n working_directory: ~/alpe-skytef-gw\\n\\n branches:\\n only:\\n - develop\\n - /feature-.*/\\n\\n steps:\\n - checkout\\n\\n # - run:\\n # command: echo 127.0.0.1 devhost | sudo tee -a /etc/hosts\\n\\n # # Create Postgres users and database\\n # # Note the YAML heredoc '|' for nicer formatting\\n # - run: |\\n # sudo -u root createuser -h localhost --superuser ubuntu \\u0026\\u0026\\n # sudo createdb -h localhost test_db\\n\\n - restore_cache:\\n keys:\\n - alpe-skytef-gw-{{ checksum \\\"Pipfile.lock\\\" }}\\n - alpe-skytef-gw-\\n\\n # - run:\\n # environment:\\n # SSH_TARGET: \\\"localhost\\\"\\n # TEST_ENV: \\\"linux\\\"\\n # command: |\\n # set -xu\\n # mkdir -p ${TEST_REPORTS}\\n # run-tests.sh\\n # cp out/tests/*.xml ${TEST_REPORTS}\\n\\n # - run: |\\n # set -xu\\n # mkdir -p /tmp/artifacts\\n # create_jars.sh ${CIRCLE_BUILD_NUM}\\n # cp *.jar /tmp/artifacts\\n\\n - run:\\n name: Install dependencies\\n command: pipenv sync --dev\\n\\n - run:\\n name: Run Tests\\n command: pipenv run pytest\\n\\n - save_cache:\\n key: alpe-skytef-gw-{{ checksum \\\"Pipfile.lock\\\" }}\\n paths:\\n - ~/.local\\n - ~/.cache\\n\\n # # Save artifacts\\n # - store_artifacts:\\n # path: /tmp/artifacts\\n # destination: build\\n\\n # # Upload test results\\n # - store_test_results:\\n # path: /tmp/test-reports\\n \\n # deploy-dev:\\n # docker:\\n # - image: ubuntu:14.04\\n # working_directory: /tmp/my-project\\n # steps:\\n # - run:\\n # name: Deploy if tests pass and branch is Staging\\n # command: ansible-playbook site.yml -i staging\\n \\n # deploy-prod:\\n # docker:\\n # - image: ubuntu:14.04\\n # working_directory: /tmp/my-project\\n # steps:\\n # - run:\\n # name: Deploy if tests pass and branch is Master\\n # command: ansible-playbook site.yml -i production\\n\\nworkflows:\\n version: 2\\n build-deploy:\\n jobs:\\n - build\\n # - deploy-dev:\\n # requires:\\n # - build\\n # filters:\\n # branches:\\n # only: develop\\n # - deploy-prod:\\n # requires:\\n # - build\\n # filters:\\n # branches:\\n # only: master\",\"AWSRegion\":\"\",\"AgentCgroupAsParent\":false,\"Debug\":false,\"LocalBuild\":true}" INFO[2018-09-20T21:49:21Z] statsd metric count=1 name=config.parsed tags="[result:succeeded]" type=counter INFO[2018-09-20T21:49:21Z] task starting allocation_id=localbuild-1537480160/59BF981 build_num= build_uri= node_index=0 node_total=1 project="git@bitbucket.org:timefinanceiro/alpe-skytef-gw.git" task_id=localbuild-1537480160 INFO[2018-09-20T21:49:21Z] config parsed branch=develop build_num= executor=docker job=build node_index=0 node_total=1 repo_url="git@bitbucket.org:timefinanceiro/alpe-skytef-gw.git" revision=a9953b37457f542b54b97ee067f4e35bbb981307 task_id=localbuild-1537480160 WARN[2018-09-20T21:49:21Z] Using dummy client for Machine INFO[2018-09-20T21:49:21Z] statsd metric count=1 name=executor.started tags="[type:docker]" type=counter INFO[2018-09-20T21:49:21Z] task started properties="map[build_agent:0.0.7725-9681bc36 executor:docker]" task=localbuild-1537480160 DEBU[2018-09-20T21:49:21Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:TaskStart properties: properties: timestamp:1537480161044 " INFO[2018-09-20T21:49:21Z] task attributes are set properties="map[type:artifacts storage-root:noop:///localbuild-1537480160/artifacts/]" task=localbuild-1537480160 DEBU[2018-09-20T21:49:21Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:TaskAddAttributes properties: properties: timestamp:1537480161052 " INFO[2018-09-20T21:49:21Z] step started properties="map[name:Spin up Environment type:spinup_environment tags:executor:docker]" step=0 task=localbuild-1537480160 DEBU[2018-09-20T21:49:21Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepStart properties: properties: properties: timestamp:1537480161053 " ====>> Spin up Environment DEBU[2018-09-20T21:49:21Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepOutput message:\"Build-agent version 0.0.7725-9681bc36 (2018-08-09T15:10:50+0000)\\n\" timestamp:1537480161053 " Build-agent version 0.0.7725-9681bc36 (2018-08-09T15:10:50+0000) INFO[2018-09-20T21:49:21Z] docker api version is set docker_api_version=1.37 INFO[2018-09-20T21:49:21Z] Preparing Docker Executor INFO[2018-09-20T21:49:21Z] checking task signals DEBU[2018-09-20T21:49:21Z] EOF in ListTaskSignals stream DEBU[2018-09-20T21:49:21Z] computed default route before bridge default_route="default via 172.17.0.1 dev eth0" INFO[2018-09-20T21:49:21Z] creating ephemeral network for task network_id=ZZZ_localbuild-1537480160/59BF981 DEBU[2018-09-20T21:49:22Z] computed default route after bridge default_route="default via 192.168.48.1 dev eth1" INFO[2018-09-20T21:49:22Z] default route changed, resetting it after="default via 192.168.48.1 dev eth1" before="default via 172.17.0.1 dev eth0" WARN[2018-09-20T21:49:22Z] error resetting default routing error="error setting ip default routing rules: exit status 2" route="default via 172.17.0.1 dev eth0" DEBU[2018-09-20T21:49:22Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepOutput message:\"Starting container circleci/python:3.6.6\\n\" timestamp:1537480162774 " Starting container circleci/python:3.6.6 DEBU[2018-09-20T21:49:22Z] should pull info image_name="circleci/python:3.6.6" should_pull=false why=cached INFO[2018-09-20T21:49:22Z] overriding entrypiont image_name="circleci/python:3.6.6" INFO[2018-09-20T21:49:23Z] statsd metric duration=1185.715994 name=docker.container.created tags="[result:succeeded type:docker]" type=timing INFO[2018-09-20T21:49:23Z] created container build_uri= container_id=ec80ae3b3793f12ec952a6d886dd53df85cb7c76326cb3875da59b3eff8eac90 image_digest="circleci/python@sha256:51cda8ba0c19bf663e62d7b6f4c91d09d42a6d61fcdf90778746437589dda7c5" image_name="circleci/python:3.6.6" is_build_container=true task_id=localbuild-1537480160 DEBU[2018-09-20T21:49:23Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepOutput message:\" using image circleci/python@sha256:51cda8ba0c19bf663e62d7b6f4c91d09d42a6d61fcdf90778746437589dda7c5\\n\" timestamp:1537480163968 " using image circleci/python@sha256:51cda8ba0c19bf663e62d7b6f4c91d09d42a6d61fcdf90778746437589dda7c5 DEBU[2018-09-20T21:49:23Z] copying "circleci" from "/opt/circleci/linux/amd64" DEBU[2018-09-20T21:49:24Z] copying "circleci" from "/opt/circleci/linux/amd64" DEBU[2018-09-20T21:49:25Z] created runner config file path=/tmp/932328385 DEBU[2018-09-20T21:49:25Z] copying "932328385" from "/tmp" INFO[2018-09-20T21:49:27Z] statsd metric duration=6838.7852 name=executor.prepared tags="[result:succeeded type:docker]" type=timing DEBU[2018-09-20T21:49:27Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepOutput message:\"\\nUsing build environment variables:\\n BASH_ENV=/tmp/.bash_env-localbuild-1537480160\\n CI=true\\n CIRCLECI=true\\n CIRCLE_BRANCH=develop\\n CIRCLE_BUILD_NUM=\\n CIRCLE_JOB=build\\n CIRCLE_NODE_INDEX=0\\n CIRCLE_NODE_TOTAL=1\\n CIRCLE_REPOSITORY_URL=git@bitbucket.org:timefinanceiro/alpe-skytef-gw.git\\n CIRCLE_SHA1=a9953b37457f542b54b97ee067f4e35bbb981307\\n CIRCLE_SHELL_ENV=/tmp/.bash_env-localbuild-1537480160\\n CIRCLE_WORKING_DIRECTORY=~/alpe-skytef-gw\\n\\n\" timestamp:1537480167894 " Using build environment variables: BASH_ENV=/tmp/.bash_env-localbuild-1537480160 CI=true CIRCLECI=true CIRCLE_BRANCH=develop CIRCLE_BUILD_NUM= CIRCLE_JOB=build CIRCLE_NODE_INDEX=0 CIRCLE_NODE_TOTAL=1 CIRCLE_REPOSITORY_URL=git@bitbucket.org:timefinanceiro/alpe-skytef-gw.git CIRCLE_SHA1=a9953b37457f542b54b97ee067f4e35bbb981307 CIRCLE_SHELL_ENV=/tmp/.bash_env-localbuild-1537480160 CIRCLE_WORKING_DIRECTORY=~/alpe-skytef-gw INFO[2018-09-20T21:49:27Z] step ended properties="map[result:success]" step=0 task=localbuild-1537480160 DEBU[2018-09-20T21:49:27Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:StepEnd properties: timestamp:1537480167897 " INFO[2018-09-20T21:49:27Z] Running task in Docker Executor DEBU[2018-09-20T21:49:27Z] runner command invocation command="[/bin/picard --config /.circleci-runner-config.json --task-data /.circleci-task-data --outerServerUrl https://circleci-internal-outer-build-agent:5500 _internal step --verbose]" INFO[2018-09-20T21:49:27Z] step started properties="map[background:false insignificant:false name:Checkout code command:#!/bin/bash -eo pipefail\nmkdir -p /home/circleci/alpe-skytef-gw && cp -r /tmp/_circleci_local_build_repo/. /home/circleci/alpe-skytef-gw shell:/bin/bash type:checkout]" step=101 task=localbuild-1537480160 DEBU[2018-09-20T21:49:27Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" stepId:101 type:StepStart properties: properties: properties: properties: properties: properties: timestamp:1537480167978 " ====>> Checkout code  #!/bin/bash -eo pipefail mkdir -p /home/circleci/alpe-skytef-gw && cp -r /tmp/_circleci_local_build_repo/. /home/circleci/alpe-skytef-gw DEBU[2018-09-20T21:49:28Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" stepId:101 type:StepOutput message:\"cp: cannot open '/tmp/_circleci_local_build_repo/./tests/__pycache__/test_inicializacao.cpython-36-PYTEST.pyc' for reading: Permission denied\\r\\n\" timestamp:1537480168010 " cp: cannot open '/tmp/_circleci_local_build_repo/./tests/__pycache__/test_inicializacao.cpython-36-PYTEST.pyc' for reading: Permission denied DEBU[2018-09-20T21:49:28Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" stepId:101 type:StepError message:\"Exited with code 1\" timestamp:1537480168012 " Error: Exited with code 1 INFO[2018-09-20T21:49:28Z] step ended properties="map[result:failed exit_code:1]" step=101 task=localbuild-1537480160 DEBU[2018-09-20T21:49:28Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" stepId:101 type:StepEnd properties: properties: timestamp:1537480168013 " Step failed Error: runner failed DEBU[2018-09-20T21:49:28Z] [hijack] End of stdout INFO[2018-09-20T21:49:28Z] process finished executing container_id=ec80ae3b3793f12ec952a6d886dd53df85cb7c76326cb3875da59b3eff8eac90 exit_code=101 running=false INFO[2018-09-20T21:49:28Z] statsd metric duration=136.030754 name=executor.run tags="[result:failed type:docker]" type=timing INFO[2018-09-20T21:49:28Z] task ended properties="map[result:failed]" task=localbuild-1537480160 DEBU[2018-09-20T21:49:28Z] Sending event to OutputProcessor event="allocationId:\"localbuild-1537480160/59BF981\" type:TaskEnd properties: timestamp:1537480168036 " Task failed INFO[2018-09-20T21:49:28Z] Cleaning up Outer INFO[2018-09-20T21:49:28Z] Cleaning up Docker Executor INFO[2018-09-20T21:49:29Z] task stats build_uri= task_id=localbuild-1537480160 totals="map[CPUUsage:1.18710478e+08 StorageReadSize:0 StorageWriteCount:0 StorageWriteSize:0 CPUUsageInUsermode:7e+07 MemoryMaxUsage:3.6069376e+07 StorageReadCount:0 NetworkRxBytes:7066 NetworkTxBytes:4508]" DEBU[2018-09-20T21:49:29Z] [hijack] End of stdout INFO[2018-09-20T21:49:29Z] process finished executing container_id=ec80ae3b3793f12ec952a6d886dd53df85cb7c76326cb3875da59b3eff8eac90 exit_code=0 running=false DEBU[2018-09-20T21:49:29Z] killed picard process in runner container_id=ec80ae3b3793f12ec952a6d886dd53df85cb7c76326cb3875da59b3eff8eac90 DEBU[2018-09-20T21:49:31Z] Restarting ListTaskSignals stream INFO[2018-09-20T21:49:31Z] checking task signals ERRO[2018-09-20T21:49:31Z] Failed to stream ListTaskSignals err="rpc error: code = Canceled desc = context canceled" DEBU[2018-09-20T21:49:31Z] removed container container_id=ec80ae3b3793f12ec952a6d886dd53df85cb7c76326cb3875da59b3eff8eac90 INFO[2018-09-20T21:49:32Z] deleting ephemeral network for task network_id=0e880a4266d6c1659ce3c948cf55a4b9ff3cc9b689a74e1a9e33075a72e3c8e4 INFO[2018-09-20T21:49:33Z] statsd metric duration=5831.96419 name=executor.cleanup tags="[result:succeeded type:docker]" type=timing INFO[2018-09-20T21:49:33Z] statsd metric count=1 name=executor.finished tags="[type:docker]" type=counter INFO[2018-09-20T21:49:33Z] Closing EventProcessorClient connection INFO[2018-09-20T21:49:33Z] Stopping DMZ Services DEBU[2018-09-20T21:49:33Z] build is aborted due to user error error="job failed"