Ceph

ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2015-01-31_06:26:17-rados-wip-sage-testing-distro-basic-multi/733423

the json format is used as a general way to get the status of the cluster and everything, while the work horse of the thrash test, Thrasher in ceph_manager.py, tries to get the status from the cluster at several different places. among other things:

• get_osd_dump_json() // osd dump --format=json
• get_pg_stats() // pg dump --format=json

so i am not sure which command printed the string not readable by the json parser. ideally, we should have the backtrace where the exception was thrown. when looking at the implementation of Greenlet class,

def _report_error(self, exc_info):
  # ....
  self.parent.handle_error(self, *exc_info)

    def handle_error(self, context, type, value, tb):
        if not issubclass(type, self.NOT_ERROR):
            self.print_exception(context, type, value, tb)
        if context is None or issubclass(type, self.SYSTEM_ERROR):
            self.handle_system_error(type, value)

in the same class

    def print_exception(self, context, type, value, tb):
        traceback.print_exception(type, value, tb)
        # ......

but i cannot find any backtrace info other than the one printed by the rethrown exception:

ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2015-01-31_06:26:17-rados-wip-sage-testing-distro-basic-multi/733423$ grep -A 10 Traceback teuthology.log
Traceback (most recent call last):
  File "/home/teuthworker/src/teuthology_master/teuthology/run_tasks.py", line 122, in run_tasks
    suppress = manager.__exit__(*exc_info)
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/var/lib/teuthworker/src/ceph-qa-suite_master/tasks/thrashosds.py", line 174, in task
    thrash_proc.do_join()
  File "/var/lib/teuthworker/src/ceph-qa-suite_master/tasks/ceph_manager.py", line 416, in do_join
    self.thread.get()
  File "/usr/lib/python2.7/dist-packages/gevent/greenlet.py", line 308, in get
    raise self._exception
--
Traceback (most recent call last):
  File "/home/teuthworker/src/teuthology_master/teuthology/contextutil.py", line 30, in nested
    yield vars
  File "/var/lib/teuthworker/src/ceph-qa-suite_master/tasks/ceph.py", line 1294, in task
    yield
  File "/home/teuthworker/src/teuthology_master/teuthology/run_tasks.py", line 122, in run_tasks
    suppress = manager.__exit__(*exc_info)
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/var/lib/teuthworker/src/ceph-qa-suite_master/tasks/thrashosds.py", line 174, in task
    thrash_proc.do_join()
--
Traceback (most recent call last):
  File "/home/teuthworker/src/teuthology_master/teuthology/contextutil.py", line 30, in nested
    yield vars
  File "/home/teuthworker/src/teuthology_master/teuthology/task/install.py", line 1269, in task
    yield
  File "/home/teuthworker/src/teuthology_master/teuthology/run_tasks.py", line 122, in run_tasks
    suppress = manager.__exit__(*exc_info)
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/var/lib/teuthworker/src/ceph-qa-suite_master/tasks/thrashosds.py", line 174, in task
    thrash_proc.do_join()

because i need to hack the greenlet to root cause the reason why the original backtrace does not show up in the log file, and i can not mess around with the lab machine (or it will be a little bit tricky to do so). i will use Loïc's container hack to start the hack.

ubuntu@teuthology:/a/sage-2015-02-17_22:30:59-rados-wip-sage-testing-distro-basic-multi/763975

fwiw it looks a bit to me like the admin socket dump_ops_in_flight command after starting the osd is hung. perhaps enabling the clietn-side debug logs, or --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monclient 20 on that ceph command, would help.. then we'd see it all in the teuthology log. or some extra logging around that code in ceph_manager.py?

thanks sage, i was on holiday last week. will look at this ticket tomorrow. seems it needs more efforts to setup a testbed for running teuthology even with loïc's hack.

Sage Weil wrote:

ubuntu@teuthology:/a/sage-2015-02-17_22:30:59-rados-wip-sage-testing-distro-basic-multi/763975

fwiw it looks a bit to me like the admin socket dump_ops_in_flight command after starting the osd is hung. perhaps enabling the clietn-side debug logs, or --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monclient 20 on that ceph command, would help.. then we'd see it all in the teuthology log.

but if the osd is hung, the asok command will timeout, and throw an exception of "timed out waiting for admin_socket to appear after osd.{id} restart'. will try out your ideas tomorrow.

or some extra logging around that code in ceph_manager.py?

yeah, will print out more info at seeing an exception if greenlet fails do this for us.

traceback.print_exception() prints to stderr, while the stderr is not logged AFAICS. might want to find a way to (monkey) patch traceback.print_exception(), or change the behaviour of gevent.Hub.print_exception().

a PR posted at https://github.com/ceph/ceph-qa-suite/pull/344 for adding logging for uncaught exception thrown by thrasher. pending on review.

Sage Weil wrote:

ubuntu@teuthology:/a/sage-2015-02-17_22:30:59-rados-wip-sage-testing-distro-basic-multi/763975

fwiw it looks a bit to me like the admin socket dump_ops_in_flight command after starting the osd is hung. perhaps enabling the clietn-side debug logs, or --log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monclient 20 on that ceph command, would help.. then we'd see it all in the teuthology log.

sage, so i will

ceph osd tell 0 injectargs '--log-to-stderr --debug-ms 1 --debug-objecter 20 --debug-monc 20'

before

ceph --admin-daemon ./out/osd.1.asok dump_ops_in_flight

and revert this debug settings after this command.

perhaps enabling the clietn-side debug logs,

sorry sage, i am not sure that i am following you, i am not sure it works in this case, as the asok command is not a native ceph command. the ceph script talks to the daemon over the UDS, so we are not likely to get the client side log. and on the server side, the OSD logger sends the log to the stderr when log-to-stderr is enabled. and, i think the OSD daemon started by the teuthology is daemonized without -d or -f option. so teuthology.log can hardly capture the log messages for the dump_ops_in_flight command.

Kefu Chai wrote:

perhaps enabling the clietn-side debug logs,

sorry sage, i am not sure that i am following you, i am not sure it works in this case, as the asok command is not a native ceph command. the ceph script talks to the daemon over the UDS, so we are not likely to get the client side log. and on the server side, the OSD logger sends the log to the stderr when log-to-stderr is enabled. and, i think the OSD daemon started by the teuthology is daemonized without -d or -f option. so teuthology.log can hardly capture the log messages for the dump_ops_in_flight command.

oh, you're right. hrm. maybe what we need is better debugging on the server side for the admin socket handling code? there is a debug_asok setting that we could bump up..