Hi everyone,
on my local test cluster mesos and aurora seem to be running out of sync:
* Mesos status: 22 active tasks by the twitter scheduler
* Aurora status: 4 active production tasks, 1 active test task
* Slave status: thermos reports 5 active tasks and 'ps aux' reports 5
active processes, i.e., aurora and thermos seem to be correct
I thought the GC was supposed to reconcile this status? I have attached
the log file of a recent gc_executor run and the stderr of one of the
faulty executors. I am omitting the logfile for the executors as these
are large and don't seem to be showing anything of interest.
Any idea what is wrong here?
Thanks,
Stephan
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0917 18:53:33.727201 1467 fetcher.cpp:76] Fetching URI
'/opt/thermos/bin/thermos_executor.sh'
I0917 18:53:33.727815 1467 fetcher.cpp:179] Copying resource from
'/opt/thermos/bin/thermos_executor.sh' to
'/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1410972813312-www-data-test-ipython-15-1de938e1-5575-4510-985b-bdf7ea8a0f01/runs/1764b62d-f26d-44c5-93ff-2058ccfedb71'
twitter.common.app debug: Initializing: twitter.common.log (Logging subsystem.)
Writing log files to disk in .
I0917 18:53:35.222765 1480 exec.cpp:132] Version: 0.20.0
I0917 18:53:35.229079 1487 exec.cpp:206] Executor registered on slave
20140917-153559-16842879-5050-2311-0
Writing log files to disk in .
Traceback (most recent call last):
File
"/.pex/install/twitter.common.exceptions-0.3.0-py2-none-any.whl.aa74e2e8535b1ea39bf9512cf70dba3e5aea7b1b/twitter.common.exceptions-0.3.0-py2-none-any.whl/twitter/common/exceptions/__init__.py",
line 126, in _excepting_run
self.__real_run(*args, **kw)
File
"/.pex/install/twitter.common.concurrent-0.3.0-py2-none-any.whl.3c9a3bf0ac76acff13a6803a37138bc9f18e54c7/twitter.common.concurrent-0.3.0-py2-none-any.whl/twitter/common/concurrent/deferred.py",
line 43, in run
self._closure()
File
"/opt/thermos/bin/thermos_executor.pex/apache/aurora/executor/aurora_executor.py",
line 258, in <lambda>
File
"/opt/thermos/bin/thermos_executor.pex/apache/aurora/executor/aurora_executor.py",
line 121, in _run
File
"/opt/thermos/bin/thermos_executor.pex/apache/aurora/executor/aurora_executor.py",
line 161, in _start_status_manager
File
"/opt/thermos/bin/thermos_executor.pex/apache/aurora/executor/common/announcer.py",
line 74, in from_assigned_task
File
"/opt/thermos/bin/thermos_executor.pex/apache/aurora/executor/common/announcer.py",
line 100, in make_serverset
File
"/.pex/install/kazoo-1.3.1-py2-none-any.whl.261c1cd5b2337063b238f0c52eeed45a1df90891/kazoo-1.3.1-py2-none-any.whl/kazoo/client.py",
line 475, in start
raise self.handler.timeout_exception("Connection time-out")
kazoo.handlers.threading.TimeoutError: Connection time-out
Log file created at: 2014/09/18 14:20:19
Running on machine: mesos-test
[DIWEF]mmdd hh:mm:ss.uuuuuu pid file:line] msg
Command line: ./gc_executor.pex
I0918 14:20:19.813986 17240 executor_base.py:45] Executor [None]: registered() called with:
I0918 14:20:19.814292 17240 executor_base.py:45] Executor [None]: ExecutorInfo: executor_id {
value: "aurora.gc"
}
resources {
name: "cpus"
type: SCALAR
scalar {
value: 0.19
}
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 15.0
}
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 127.0
}
}
command {
uris {
value: "/opt/thermos/bin/gc_executor.pex"
executable: true
}
value: "./gc_executor.pex"
}
framework_id {
value: "20140916-112621-16842879-5050-2321-0001"
}
name: "aurora.gc"
source: "mesos-test"
I0918 14:20:19.814481 17240 executor_base.py:45] Executor [None]: FrameworkInfo: user: "root"
name: "TwitterScheduler"
id {
value: "20140916-112621-16842879-5050-2321-0001"
}
failover_timeout: 1814400.0
checkpoint: false
hostname: "mesos-test.local"
I0918 14:20:19.815015 17240 executor_base.py:45] Executor [None]: SlaveInfo: hostname: "mesos-test"
webui_hostname: "mesos-test"
resources {
name: "cpus"
type: SCALAR
scalar {
value: 8.0
}
role: "*"
}
resources {
name: "mem"
type: SCALAR
scalar {
value: 15061.0
}
role: "*"
}
resources {
name: "disk"
type: SCALAR
scalar {
value: 919916.0
}
role: "*"
}
resources {
name: "ports"
type: RANGES
ranges {
range {
begin: 31000
end: 32000
}
}
role: "*"
}
attributes {
name: "host"
type: TEXT
text {
value: "mesos-test"
}
}
attributes {
name: "rack"
type: TEXT
text {
value: "unspecified"
}
}
id {
value: "20140917-153559-16842879-5050-2311-0"
}
checkpoint: true
port: 5051
I0918 14:20:19.816088 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: launchTask() got task_id: system-gc-be90fed0-705c-4ee5-a35b-a215774abe78
I0918 14:20:19.817018 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => Adding system-gc-be90fed0-705c-4ee5-a35b-a215774abe78 to GC queue
I0918 14:25:19.798598 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Launching garbage collection [task_id=system-gc-be90fed0-705c-4ee5-a35b-a215774abe78]
I0918 14:25:19.801215 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Told to retain the following task ids:
I0918 14:25:19.801450 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972345960-www-data-test-ipython-0-37b0ba1e-7908-4d54-9997-be26566a914c as KILLED
I0918 14:25:19.801644 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410971897084-www-data-test-ipython-1-7f9a167c-a18a-4432-9b13-f26124d6d023 as KILLED
I0918 14:25:19.801825 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410973430367-www-data-prod-ipython-0-536fbc07-52e7-4b7f-8b0a-2fe7b9aadcb4 as LOST
I0918 14:25:19.802001 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a as RUNNING
I0918 14:25:19.802177 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972821517-www-data-test-ipython-16-cffdf778-e16f-45c8-9e99-aabd84a393b9 as LOST
I0918 14:25:19.802351 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c as RUNNING
I0918 14:25:19.802525 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972646333-www-data-test-ipython-4-a88e2b91-631e-4335-b26b-bf2d24c4687a as KILLED
I0918 14:25:19.802697 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410965355116-www-data-test-ipython-0-bb4af0c4-c0e9-4e3b-97c4-5cb4be1a9774 as KILLED
I0918 14:25:19.802892 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972461004-www-data-test-ipython-2-74cc2346-0d1f-4bfb-ba4b-9cd0003d8446 as KILLED
I0918 14:25:19.803062 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972708557-www-data-test-ipython-7-17e0da7b-3cdd-4294-b042-d906f396b3ed as LOST
I0918 14:25:19.803316 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972706337-www-data-test-ipython-6-9b58a2f5-7158-4cd8-ac24-f49d13a6d84c as LOST
I0918 14:25:19.803441 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d as RUNNING
I0918 14:25:19.803514 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972828526-www-data-test-ipython-17-0b64f5a2-fc43-404a-8bef-042d009bcfe0 as LOST
I0918 14:25:19.803590 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10 as RUNNING
I0918 14:25:19.803663 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972784752-www-data-test-ipython-14-0009d66f-0549-4653-91ef-a7a04ba90b8e as LOST
I0918 14:25:19.803735 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972761426-www-data-test-ipython-11-8b014d70-2670-4871-95c9-2c03289a917c as LOST
I0918 14:25:19.803807 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972757365-www-data-test-ipython-10-3e4177db-bf53-4fca-8de7-3fc6ef327b3d as LOST
I0918 14:25:19.803879 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517 as RUNNING
I0918 14:25:19.803952 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653317-www-data-test-ipython-0-93a281b7-f974-46bb-8516-bf731c8ac5dc as KILLED
I0918 14:25:19.804045 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972776634-www-data-test-ipython-13-76dfbd81-8cb0-481e-ad76-dac25d2f22dc as LOST
I0918 14:25:19.804141 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972828526-www-data-test-ipython-18-3f7ffcbd-2b8e-427e-9928-7e00c9dbe807 as LOST
I0918 14:25:19.804234 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972405999-www-data-test-ipython-1-cda1a0c7-9015-4726-90bb-5812daa39e11 as KILLED
I0918 14:25:19.804328 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972813312-www-data-test-ipython-15-1de938e1-5575-4510-985b-bdf7ea8a0f01 as LOST
I0918 14:25:19.804419 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972720764-www-data-test-ipython-9-66890b2b-3c69-4e36-a564-290e3245606b as LOST
I0918 14:25:19.804508 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653317-www-data-test-ipython-1-8239770b-dce4-452c-97b4-9e9b092c88ec as KILLED
I0918 14:25:19.804600 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-4-e6d39c47-cd8b-4813-be10-99d7ee16efdf as KILLED
I0918 14:25:19.804732 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410973996594-www-data-prod-ipython-0-d89ec4b2-425d-4ded-afbe-4e224a339788 as LOST
I0918 14:25:19.804841 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410971897084-www-data-test-ipython-0-88b2bf6a-3192-4da4-9ac8-7d4b1c3d6933 as KILLED
I0918 14:25:19.804934 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653318-www-data-test-ipython-2-80ddd470-ffc6-4f3b-b5c9-a24d2d70c352 as KILLED
I0918 14:25:19.805027 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972712634-www-data-test-ipython-8-0afe9991-082f-4c7c-bc8f-196bc047b1ad as LOST
I0918 14:25:19.805131 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972768471-www-data-test-ipython-12-0672d373-594a-4e78-943c-bdf61668b463 as LOST
I0918 14:25:19.805224 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972646333-www-data-test-ipython-3-ce800c52-7f3f-4d99-812a-41a1bf791a38 as KILLED
I0918 14:25:19.805315 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972702277-www-data-test-ipython-5-6a5dfdf7-06dc-45ec-a644-ef3959d1f739 as LOST
I0918 14:25:19.805408 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410965389188-www-data-test-ipython-1-0fdf9a5f-1074-408b-aa24-82569b7249b2 as KILLED
I0918 14:25:19.805500 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972836651-www-data-test-ipython-19-c2ba198f-383d-43c9-a833-313560bfafad as LOST
I0918 14:25:19.805592 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Local active tasks:
I0918 14:25:19.805675 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10
I0918 14:25:19.805749 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517
I0918 14:25:19.805821 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c
I0918 14:25:19.805893 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a
I0918 14:25:19.805967 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d
I0918 14:25:19.806037 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Local finished tasks:
I0918 14:25:19.806108 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972345960-www-data-test-ipython-0-37b0ba1e-7908-4d54-9997-be26566a914c
I0918 14:25:19.806277 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410971897084-www-data-test-ipython-1-7f9a167c-a18a-4432-9b13-f26124d6d023
I0918 14:25:19.806365 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410973430367-www-data-prod-ipython-0-536fbc07-52e7-4b7f-8b0a-2fe7b9aadcb4
I0918 14:25:19.806454 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972821517-www-data-test-ipython-16-cffdf778-e16f-45c8-9e99-aabd84a393b9
I0918 14:25:19.806544 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972646333-www-data-test-ipython-4-a88e2b91-631e-4335-b26b-bf2d24c4687a
I0918 14:25:19.806633 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410965355116-www-data-test-ipython-0-bb4af0c4-c0e9-4e3b-97c4-5cb4be1a9774
I0918 14:25:19.806721 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972836651-www-data-test-ipython-19-c2ba198f-383d-43c9-a833-313560bfafad
I0918 14:25:19.806809 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972708557-www-data-test-ipython-7-17e0da7b-3cdd-4294-b042-d906f396b3ed
I0918 14:25:19.806896 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972706337-www-data-test-ipython-6-9b58a2f5-7158-4cd8-ac24-f49d13a6d84c
I0918 14:25:19.806986 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972828526-www-data-test-ipython-17-0b64f5a2-fc43-404a-8bef-042d009bcfe0
I0918 14:25:19.807080 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972784752-www-data-test-ipython-14-0009d66f-0549-4653-91ef-a7a04ba90b8e
I0918 14:25:19.807194 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972761426-www-data-test-ipython-11-8b014d70-2670-4871-95c9-2c03289a917c
I0918 14:25:19.807332 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972757365-www-data-test-ipython-10-3e4177db-bf53-4fca-8de7-3fc6ef327b3d
I0918 14:25:19.807431 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653317-www-data-test-ipython-0-93a281b7-f974-46bb-8516-bf731c8ac5dc
I0918 14:25:19.807521 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972776634-www-data-test-ipython-13-76dfbd81-8cb0-481e-ad76-dac25d2f22dc
I0918 14:25:19.807610 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972828526-www-data-test-ipython-18-3f7ffcbd-2b8e-427e-9928-7e00c9dbe807
I0918 14:25:19.807699 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972405999-www-data-test-ipython-1-cda1a0c7-9015-4726-90bb-5812daa39e11
I0918 14:25:19.807789 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972813312-www-data-test-ipython-15-1de938e1-5575-4510-985b-bdf7ea8a0f01
I0918 14:25:19.807877 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972720764-www-data-test-ipython-9-66890b2b-3c69-4e36-a564-290e3245606b
I0918 14:25:19.807965 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653317-www-data-test-ipython-1-8239770b-dce4-452c-97b4-9e9b092c88ec
I0918 14:25:19.808078 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1411025898589-www-data-prod-ipython-4-e6d39c47-cd8b-4813-be10-99d7ee16efdf
I0918 14:25:19.808168 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410973996594-www-data-prod-ipython-0-d89ec4b2-425d-4ded-afbe-4e224a339788
I0918 14:25:19.808259 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410971897084-www-data-test-ipython-0-88b2bf6a-3192-4da4-9ac8-7d4b1c3d6933
I0918 14:25:19.808348 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972653318-www-data-test-ipython-2-80ddd470-ffc6-4f3b-b5c9-a24d2d70c352
I0918 14:25:19.808435 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972712634-www-data-test-ipython-8-0afe9991-082f-4c7c-bc8f-196bc047b1ad
I0918 14:25:19.808522 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972768471-www-data-test-ipython-12-0672d373-594a-4e78-943c-bdf61668b463
I0918 14:25:19.808609 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972646333-www-data-test-ipython-3-ce800c52-7f3f-4d99-812a-41a1bf791a38
I0918 14:25:19.808700 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972702277-www-data-test-ipython-5-6a5dfdf7-06dc-45ec-a644-ef3959d1f739
I0918 14:25:19.808789 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410965389188-www-data-test-ipython-1-0fdf9a5f-1074-408b-aa24-82569b7249b2
I0918 14:25:19.808871 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: => 1410972461004-www-data-test-ipython-2-74cc2346-0d1f-4bfb-ba4b-9cd0003d8446
I0918 14:25:19.814987 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Executor sandboxes retained by Mesos:
I0918 14:25:19.815165 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410965355116-www-data-test-ipython-0-bb4af0c4-c0e9-4e3b-97c4-5cb4be1a9774
I0918 14:25:19.815268 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410965389188-www-data-test-ipython-1-0fdf9a5f-1074-408b-aa24-82569b7249b2
I0918 14:25:19.815361 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410971897084-www-data-test-ipython-0-88b2bf6a-3192-4da4-9ac8-7d4b1c3d6933
I0918 14:25:19.815454 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410971897084-www-data-test-ipython-1-7f9a167c-a18a-4432-9b13-f26124d6d023
I0918 14:25:19.815563 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972345960-www-data-test-ipython-0-37b0ba1e-7908-4d54-9997-be26566a914c
I0918 14:25:19.815658 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972405999-www-data-test-ipython-1-cda1a0c7-9015-4726-90bb-5812daa39e11
I0918 14:25:19.815749 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972461004-www-data-test-ipython-2-74cc2346-0d1f-4bfb-ba4b-9cd0003d8446
I0918 14:25:19.815896 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972646333-www-data-test-ipython-3-ce800c52-7f3f-4d99-812a-41a1bf791a38
I0918 14:25:19.816035 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972646333-www-data-test-ipython-4-a88e2b91-631e-4335-b26b-bf2d24c4687a
I0918 14:25:19.816133 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972653317-www-data-test-ipython-0-93a281b7-f974-46bb-8516-bf731c8ac5dc
I0918 14:25:19.816225 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972653317-www-data-test-ipython-1-8239770b-dce4-452c-97b4-9e9b092c88ec
I0918 14:25:19.816314 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972653318-www-data-test-ipython-2-80ddd470-ffc6-4f3b-b5c9-a24d2d70c352
I0918 14:25:19.816404 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972702277-www-data-test-ipython-5-6a5dfdf7-06dc-45ec-a644-ef3959d1f739
I0918 14:25:19.816494 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972706337-www-data-test-ipython-6-9b58a2f5-7158-4cd8-ac24-f49d13a6d84c
I0918 14:25:19.816582 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972708557-www-data-test-ipython-7-17e0da7b-3cdd-4294-b042-d906f396b3ed
I0918 14:25:19.816672 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972712634-www-data-test-ipython-8-0afe9991-082f-4c7c-bc8f-196bc047b1ad
I0918 14:25:19.816761 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972720764-www-data-test-ipython-9-66890b2b-3c69-4e36-a564-290e3245606b
I0918 14:25:19.816852 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972757365-www-data-test-ipython-10-3e4177db-bf53-4fca-8de7-3fc6ef327b3d
I0918 14:25:19.816941 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972761426-www-data-test-ipython-11-8b014d70-2670-4871-95c9-2c03289a917c
I0918 14:25:19.817032 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972768471-www-data-test-ipython-12-0672d373-594a-4e78-943c-bdf61668b463
I0918 14:25:19.817193 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972776634-www-data-test-ipython-13-76dfbd81-8cb0-481e-ad76-dac25d2f22dc
I0918 14:25:19.817286 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972784752-www-data-test-ipython-14-0009d66f-0549-4653-91ef-a7a04ba90b8e
I0918 14:25:19.817358 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972813312-www-data-test-ipython-15-1de938e1-5575-4510-985b-bdf7ea8a0f01
I0918 14:25:19.817431 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972821517-www-data-test-ipython-16-cffdf778-e16f-45c8-9e99-aabd84a393b9
I0918 14:25:19.817503 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972828526-www-data-test-ipython-17-0b64f5a2-fc43-404a-8bef-042d009bcfe0
I0918 14:25:19.817575 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972828526-www-data-test-ipython-18-3f7ffcbd-2b8e-427e-9928-7e00c9dbe807
I0918 14:25:19.817648 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410972836651-www-data-test-ipython-19-c2ba198f-383d-43c9-a833-313560bfafad
I0918 14:25:19.817730 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410973430367-www-data-prod-ipython-0-536fbc07-52e7-4b7f-8b0a-2fe7b9aadcb4
I0918 14:25:19.817806 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1410973996594-www-data-prod-ipython-0-d89ec4b2-425d-4ded-afbe-4e224a339788
I0918 14:25:19.817878 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d
I0918 14:25:19.817953 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10
I0918 14:25:19.818026 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a
I0918 14:25:19.818098 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517
I0918 14:25:19.818170 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411025898589-www-data-prod-ipython-4-e6d39c47-cd8b-4813-be10-99d7ee16efdf
I0918 14:25:19.818242 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: 1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c
I0918 14:25:19.818399 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Updating system-gc-be90fed0-705c-4ee5-a35b-a215774abe78 => FINISHED
I0918 14:25:19.818478 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Reason: Garbage collection finished.
I0918 14:25:19.818739 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Garbage collection complete [task_id=system-gc-be90fed0-705c-4ee5-a35b-a215774abe78]
I0918 14:25:19.818830 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Checking for orphaned tasks
I0918 14:25:19.819569 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10
D0918 14:25:19.820072 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:25:19.820341 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029251794, task_id='1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/runs/917d0236-390c-4ac0-b9c0-fbd8033f80e5/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/runs/917d0236-390c-4ac0-b9c0-fbd8033f80e5/sandbox/.logs', ports={'aurora': 31275, 'http': 31275}, user='www-data')
D0918 14:25:19.820580 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:25:19.821001 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:25:19.821351 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:25:19.821690 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:25:19.821902 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:25:19.822117 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:25:19.822354 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:25:19.822469 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:25:19.822576 17240 muxer.py:40] registering virtualenv
D0918 14:25:19.822649 17240 muxer.py:40] registering notebook
D0918 14:25:19.822793 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.virtualenv
D0918 14:25:19.822911 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:25:19.823127 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.823224 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:25:19.823333 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.notebook
D0918 14:25:19.823431 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:25:19.823622 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.823715 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:25:19.824132 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.virtualenv has no data (current offset = 186)
D0918 14:25:19.824423 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.notebook has no data (current offset = 120)
D0918 14:25:19.824526 17240 muxer.py:155] select() returning 5 updates:
D0918 14:25:19.824640 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13199, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029251.953819), runner_header=None)
D0918 14:25:19.824740 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029251.96472, coordinator_pid=None, pid=13200, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:25:19.824839 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029259.161254, fork_time=None), runner_header=None)
D0918 14:25:19.824944 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13285, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029260.012171), runner_header=None)
D0918 14:25:19.825047 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029260.024323, coordinator_pid=None, pid=13286, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:25:19.825623 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:25:19.825737 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517
D0918 14:25:19.826004 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:25:19.826240 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029301777, task_id='1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/runs/4474d08b-a9b4-4cd6-b2ed-88fa80c4ddf8/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/runs/4474d08b-a9b4-4cd6-b2ed-88fa80c4ddf8/sandbox/.logs', ports={'aurora': 31050, 'http': 31050}, user='www-data')
D0918 14:25:19.826399 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:25:19.826622 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:25:19.826837 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:25:19.827070 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:25:19.827322 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:25:19.827538 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:25:19.827747 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:25:19.827936 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:25:19.828092 17240 muxer.py:40] registering virtualenv
D0918 14:25:19.828182 17240 muxer.py:40] registering notebook
D0918 14:25:19.828291 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.virtualenv
D0918 14:25:19.828392 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:25:19.828584 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.828674 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:25:19.828780 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.notebook
D0918 14:25:19.828905 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:25:19.829096 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.829184 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:25:19.829525 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.virtualenv has no data (current offset = 186)
D0918 14:25:19.829899 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.notebook has no data (current offset = 120)
D0918 14:25:19.830017 17240 muxer.py:155] select() returning 5 updates:
D0918 14:25:19.830117 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13673, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029301.935564), runner_header=None)
D0918 14:25:19.830218 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029301.945327, coordinator_pid=None, pid=13674, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:25:19.830317 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029309.171206, fork_time=None), runner_header=None)
D0918 14:25:19.830415 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13763, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029309.992783), runner_header=None)
D0918 14:25:19.830513 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029310.004811, coordinator_pid=None, pid=13764, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:25:19.832057 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:25:19.832228 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c
D0918 14:25:19.832552 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:25:19.832803 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411042169824, task_id='1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/runs/446e3e00-7295-4584-a1a4-5de1633617af/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/runs/446e3e00-7295-4584-a1a4-5de1633617af/sandbox/.logs', ports={'aurora': 31123, 'http': 31123}, user='www-data')
D0918 14:25:19.832966 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:25:19.833179 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:25:19.833381 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:25:19.833554 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:25:19.833715 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:25:19.833887 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:25:19.834058 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:25:19.834166 17240 recordio.py:137] <fdopen> has no data (current offset = 1143)
D0918 14:25:19.834256 17240 muxer.py:40] registering virtualenv
D0918 14:25:19.834326 17240 muxer.py:40] registering notebook
D0918 14:25:19.834414 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.virtualenv
D0918 14:25:19.834495 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:25:19.834651 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.834722 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:25:19.834809 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.notebook
D0918 14:25:19.834887 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:25:19.835040 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.835109 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:25:19.835457 17240 recordio.py:137] /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.virtualenv has no data (current offset = 186)
D0918 14:25:19.835735 17240 recordio.py:137] /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.notebook has no data (current offset = 120)
D0918 14:25:19.835828 17240 muxer.py:155] select() returning 5 updates:
D0918 14:25:19.835937 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=15386, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411042169.98548), runner_header=None)
D0918 14:25:19.836091 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411042170.093963, coordinator_pid=None, pid=15387, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:25:19.836225 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411042178.421513, fork_time=None), runner_header=None)
D0918 14:25:19.836328 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=15541, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411042179.045228), runner_header=None)
D0918 14:25:19.836445 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411042179.057261, coordinator_pid=None, pid=15542, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:25:19.837057 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:25:19.837168 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a
D0918 14:25:19.837445 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:25:19.837760 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029284858, task_id='1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/runs/46bd5d06-b69a-4cd1-b69c-8fe5629c0134/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/runs/46bd5d06-b69a-4cd1-b69c-8fe5629c0134/sandbox/.logs', ports={'aurora': 31765, 'http': 31765}, user='www-data')
D0918 14:25:19.837930 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:25:19.838143 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:25:19.838356 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:25:19.838565 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:25:19.838762 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:25:19.838980 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:25:19.839195 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:25:19.839310 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:25:19.839401 17240 muxer.py:40] registering virtualenv
D0918 14:25:19.839473 17240 muxer.py:40] registering notebook
D0918 14:25:19.839560 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.virtualenv
D0918 14:25:19.839637 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:25:19.839795 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.839864 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:25:19.839950 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.notebook
D0918 14:25:19.840111 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:25:19.840302 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.840389 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:25:19.840724 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.virtualenv has no data (current offset = 186)
D0918 14:25:19.840997 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.notebook has no data (current offset = 120)
D0918 14:25:19.841088 17240 muxer.py:155] select() returning 5 updates:
D0918 14:25:19.841185 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13481, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029285.020313), runner_header=None)
D0918 14:25:19.841293 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029285.031318, coordinator_pid=None, pid=13482, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:25:19.841397 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029292.29959, fork_time=None), runner_header=None)
D0918 14:25:19.841495 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13576, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029293.07627), runner_header=None)
D0918 14:25:19.841573 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029293.087377, coordinator_pid=None, pid=13577, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:25:19.841933 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:25:19.842020 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d
D0918 14:25:19.842240 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:25:19.842432 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029235758, task_id='1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/runs/3b177f56-c659-4ae8-bd42-f887eef40fc3/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/runs/3b177f56-c659-4ae8-bd42-f887eef40fc3/sandbox/.logs', ports={'aurora': 31394, 'http': 31394}, user='www-data')
D0918 14:25:19.842561 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:25:19.842731 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:25:19.842904 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:25:19.843075 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:25:19.843310 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:25:19.843486 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:25:19.843656 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:25:19.843765 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:25:19.843856 17240 muxer.py:40] registering virtualenv
D0918 14:25:19.843928 17240 muxer.py:40] registering notebook
D0918 14:25:19.844043 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.virtualenv
D0918 14:25:19.844126 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:25:19.844286 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.844357 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:25:19.844443 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.notebook
D0918 14:25:19.844526 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:25:19.844682 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:25:19.844754 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:25:19.845105 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.virtualenv has no data (current offset = 186)
D0918 14:25:19.845376 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.notebook has no data (current offset = 120)
D0918 14:25:19.845464 17240 muxer.py:155] select() returning 5 updates:
D0918 14:25:19.845561 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13013, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029235.922947), runner_header=None)
D0918 14:25:19.845719 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029235.933481, coordinator_pid=None, pid=13017, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:25:19.845824 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029243.240763, fork_time=None), runner_header=None)
D0918 14:25:19.845921 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13120, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029243.983617), runner_header=None)
D0918 14:25:19.846018 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029243.994718, coordinator_pid=None, pid=13121, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:25:19.846431 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:30:19.846962 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Checking for orphaned tasks
I0918 14:30:19.848644 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10
D0918 14:30:19.849363 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:30:19.849837 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029251794, task_id='1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/runs/917d0236-390c-4ac0-b9c0-fbd8033f80e5/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/runs/917d0236-390c-4ac0-b9c0-fbd8033f80e5/sandbox/.logs', ports={'aurora': 31275, 'http': 31275}, user='www-data')
D0918 14:30:19.850142 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:30:19.850578 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:30:19.850977 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:30:19.851376 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:30:19.851744 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:30:19.852215 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:30:19.852646 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:30:19.852929 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:30:19.853148 17240 muxer.py:40] registering virtualenv
D0918 14:30:19.853308 17240 muxer.py:40] registering notebook
D0918 14:30:19.853509 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.virtualenv
D0918 14:30:19.853691 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:30:19.854053 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.854218 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:30:19.854418 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.notebook
D0918 14:30:19.854597 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:30:19.854948 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.855112 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:30:19.855751 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.virtualenv has no data (current offset = 186)
D0918 14:30:19.856313 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-1-0b7ad78b-d639-4774-91b0-2e5da0c9bb10/coordinator.notebook has no data (current offset = 120)
D0918 14:30:19.856493 17240 muxer.py:155] select() returning 5 updates:
D0918 14:30:19.856683 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13199, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029251.953819), runner_header=None)
D0918 14:30:19.856903 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029251.96472, coordinator_pid=None, pid=13200, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:30:19.857091 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029259.161254, fork_time=None), runner_header=None)
D0918 14:30:19.857281 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13285, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029260.012171), runner_header=None)
D0918 14:30:19.857470 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029260.024323, coordinator_pid=None, pid=13286, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:30:19.858336 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:30:19.858536 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517
D0918 14:30:19.859030 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:30:19.859476 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029301777, task_id='1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/runs/4474d08b-a9b4-4cd6-b2ed-88fa80c4ddf8/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/runs/4474d08b-a9b4-4cd6-b2ed-88fa80c4ddf8/sandbox/.logs', ports={'aurora': 31050, 'http': 31050}, user='www-data')
D0918 14:30:19.859791 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:30:19.860235 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:30:19.860642 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:30:19.861099 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:30:19.861299 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:30:19.861469 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:30:19.861640 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:30:19.861749 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:30:19.861840 17240 muxer.py:40] registering virtualenv
D0918 14:30:19.861910 17240 muxer.py:40] registering notebook
D0918 14:30:19.861995 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.virtualenv
D0918 14:30:19.862075 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:30:19.862234 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.862304 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:30:19.862390 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.notebook
D0918 14:30:19.862466 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:30:19.862621 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.862689 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:30:19.863070 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.virtualenv has no data (current offset = 186)
D0918 14:30:19.863193 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-3-6b74ea6a-8e0f-45a7-aae7-32ca0b93a517/coordinator.notebook has no data (current offset = 120)
D0918 14:30:19.863265 17240 muxer.py:155] select() returning 5 updates:
D0918 14:30:19.863344 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13673, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029301.935564), runner_header=None)
D0918 14:30:19.863426 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029301.945327, coordinator_pid=None, pid=13674, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:30:19.863507 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029309.171206, fork_time=None), runner_header=None)
D0918 14:30:19.863584 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13763, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029309.992783), runner_header=None)
D0918 14:30:19.863663 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029310.004811, coordinator_pid=None, pid=13764, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:30:19.864063 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:30:19.864156 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c
D0918 14:30:19.864373 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:30:19.864571 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411042169824, task_id='1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/runs/446e3e00-7295-4584-a1a4-5de1633617af/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/runs/446e3e00-7295-4584-a1a4-5de1633617af/sandbox/.logs', ports={'aurora': 31123, 'http': 31123}, user='www-data')
D0918 14:30:19.864700 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:30:19.864871 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:30:19.865056 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:30:19.865230 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:30:19.865389 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:30:19.865557 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:30:19.865871 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:30:19.865972 17240 recordio.py:137] <fdopen> has no data (current offset = 1143)
D0918 14:30:19.866034 17240 muxer.py:40] registering virtualenv
D0918 14:30:19.866034 17240 muxer.py:40] registering notebook
D0918 14:30:19.866090 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.virtualenv
D0918 14:30:19.866168 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:30:19.866326 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.866395 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:30:19.866481 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.notebook
D0918 14:30:19.866559 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:30:19.866712 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.866782 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:30:19.867067 17240 recordio.py:137] /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.virtualenv has no data (current offset = 186)
D0918 14:30:19.867290 17240 recordio.py:137] /var/run/thermos/checkpoints/1411026801656-www-data-test-ipython-19-b585ac00-8050-4186-9c03-084c6917544c/coordinator.notebook has no data (current offset = 120)
D0918 14:30:19.867363 17240 muxer.py:155] select() returning 5 updates:
D0918 14:30:19.867443 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=15386, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411042169.98548), runner_header=None)
D0918 14:30:19.867522 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411042170.093963, coordinator_pid=None, pid=15387, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:30:19.867610 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411042178.421513, fork_time=None), runner_header=None)
D0918 14:30:19.867691 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=15541, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411042179.045228), runner_header=None)
D0918 14:30:19.867770 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411042179.057261, coordinator_pid=None, pid=15542, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:30:19.868189 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:30:19.868280 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a
D0918 14:30:19.868557 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:30:19.868798 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029284858, task_id='1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/runs/46bd5d06-b69a-4cd1-b69c-8fe5629c0134/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/runs/46bd5d06-b69a-4cd1-b69c-8fe5629c0134/sandbox/.logs', ports={'aurora': 31765, 'http': 31765}, user='www-data')
D0918 14:30:19.868971 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:30:19.869256 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:30:19.869398 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:30:19.869611 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:30:19.869836 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:30:19.870008 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:30:19.870179 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:30:19.870290 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:30:19.870379 17240 muxer.py:40] registering virtualenv
D0918 14:30:19.870492 17240 muxer.py:40] registering notebook
D0918 14:30:19.870583 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.virtualenv
D0918 14:30:19.870661 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:30:19.870819 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.870891 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:30:19.870978 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.notebook
D0918 14:30:19.871056 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:30:19.871211 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.871279 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:30:19.871589 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.virtualenv has no data (current offset = 186)
D0918 14:30:19.871834 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898589-www-data-prod-ipython-2-393050b5-21f8-47b0-a498-a53218f23c6a/coordinator.notebook has no data (current offset = 120)
D0918 14:30:19.871908 17240 muxer.py:155] select() returning 5 updates:
D0918 14:30:19.872009 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13481, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029285.020313), runner_header=None)
D0918 14:30:19.872096 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029285.031318, coordinator_pid=None, pid=13482, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:30:19.872196 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029292.29959, fork_time=None), runner_header=None)
D0918 14:30:19.872292 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13576, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029293.07627), runner_header=None)
D0918 14:30:19.872389 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029293.087377, coordinator_pid=None, pid=13577, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:30:19.872829 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
I0918 14:30:19.872967 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: Inspecting running task: 1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d
D0918 14:30:19.873284 17240 ckpt.py:351] Flipping task state from (undefined) to ACTIVE
D0918 14:30:19.873580 17240 ckpt.py:331] Initializing TaskRunner header to RunnerHeader(launch_time_ms=1411029235758, task_id='1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d', hostname='mesos-test', sandbox='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/runs/3b177f56-c659-4ae8-bd42-f887eef40fc3/sandbox', log_dir='/tmp/mesos/slaves/20140917-153559-16842879-5050-2311-0/frameworks/20140916-112621-16842879-5050-2321-0001/executors/thermos-1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/runs/3b177f56-c659-4ae8-bd42-f887eef40fc3/sandbox/.logs', ports={'aurora': 31394, 'http': 31394}, user='www-data')
D0918 14:30:19.873717 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=0
D0918 14:30:19.873891 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=1
D0918 14:30:19.874064 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=2
D0918 14:30:19.874236 17240 ckpt.py:382] Running state machine for process=virtualenv/seq=3
D0918 14:30:19.874397 17240 ckpt.py:382] Running state machine for process=notebook/seq=0
D0918 14:30:19.874566 17240 ckpt.py:382] Running state machine for process=notebook/seq=1
D0918 14:30:19.874737 17240 ckpt.py:382] Running state machine for process=notebook/seq=2
D0918 14:30:19.874845 17240 recordio.py:137] <fdopen> has no data (current offset = 1140)
D0918 14:30:19.874936 17240 muxer.py:40] registering virtualenv
D0918 14:30:19.875006 17240 muxer.py:40] registering notebook
D0918 14:30:19.875092 17240 muxer.py:50] ProcessMuxer binding virtualenv => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.virtualenv
D0918 14:30:19.875176 17240 muxer.py:65] Fast forwarding virtualenv stream to seq=0
D0918 14:30:19.875333 17240 muxer.py:79] Over-seeked virtualenv [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.875406 17240 muxer.py:87] Only able to fast forward to virtualenv@sequence=-1, high watermark is 0
D0918 14:30:19.875493 17240 muxer.py:50] ProcessMuxer binding notebook => /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.notebook
D0918 14:30:19.875571 17240 muxer.py:65] Fast forwarding notebook stream to seq=0
D0918 14:30:19.875727 17240 muxer.py:79] Over-seeked notebook [watermark = 1, high watermark = 0], rewinding.
W0918 14:30:19.875798 17240 muxer.py:87] Only able to fast forward to notebook@sequence=-1, high watermark is 0
D0918 14:30:19.876112 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.virtualenv has no data (current offset = 186)
D0918 14:30:19.876341 17240 recordio.py:137] /var/run/thermos/checkpoints/1411025898588-www-data-prod-ipython-0-828d2a96-269d-44b5-9023-cdd71072279d/coordinator.notebook has no data (current offset = 120)
D0918 14:30:19.876415 17240 muxer.py:155] select() returning 5 updates:
D0918 14:30:19.876496 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='virtualenv', start_time=None, coordinator_pid=13013, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029235.922947), runner_header=None)
D0918 14:30:19.876734 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='virtualenv', start_time=1411029235.933481, coordinator_pid=None, pid=13017, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
D0918 14:30:19.876765 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=3, process='virtualenv', start_time=None, coordinator_pid=None, pid=None, return_code=0, state=3, stop_time=1411029243.240763, fork_time=None), runner_header=None)
D0918 14:30:19.876844 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=1, process='notebook', start_time=None, coordinator_pid=13120, pid=None, return_code=None, state=1, stop_time=None, fork_time=1411029243.983617), runner_header=None)
D0918 14:30:19.876960 17240 muxer.py:157] = RunnerCkpt(task_status=None, process_status=ProcessStatus(seq=2, process='notebook', start_time=1411029243.994718, coordinator_pid=None, pid=13121, return_code=None, state=2, stop_time=None, fork_time=None), runner_header=None)
I0918 14:30:19.877402 17240 executor_base.py:45] Executor [20140917-153559-16842879-5050-2311-0]: - Runner is dead but under LOST threshold.
