nexedi / cloudooo

added 1 commit

a0ad16c7 - stop hanging uno thread

It's minor, but the generally recommended syntax for logging is

          logger.debug("Process %s killed with returncode %s", process_pid, self.process.returncode)

so that if log level is not enabled the string is not built.

fixed

BTW, the process management code in cloudooo looks incorrect (before these changes).

According to psutil docs returncode is set only after wait.

Also, the parent process have to read the return code of their sub process, otherwise process remains as zombie. I don't see where cloudooo is doing this, but it does not leak so many zombie processes, so I might be missing something.

For the records, psutil has a nice recipe for terminate https://psutil.readthedocs.io/en/latest/#terminate-my-children which is more or less what this method was trying to do.

Thank you, your comment is very important. I adjusted waiting returncode. But I did not implement the recursive termination because it will not help us if the binary we run wants to leave an invisible subprocess. So I see a safe solution to this problem is to launch it from another user controlled by cloudooo master, but I do not know how to make it compatible with slapos.

Thanks, this way of managing processes looks much better now !

"Invisible process", are you referring to Y in this scenario:

A ─┐
   │
   ├─ B (child) ─┐
   │             └─ X (grandchild) ─┐
   │                                └─ Y (great grandchild)

Y sends signal to terminate X, Y has no parent process and is "reparented" to 1:

A ─┐
   │
   └─ B (child)

1 ─┐
   │
   └─ Y (child)

If yes, then using another unix user can be solution (just kill all processes owned by this user), but this is not really possible in current SlapOS as far as I know. One linux only solution is to use pid namespaces, but this idea was not accepted when we wanted to do it in SlapOS, because SlapOS aims at being portable and not only linux. I guess it would be same in cloudooo.

But is this scenario really happening ? I don't think libreoffice is daemonizing itself, is it ?

( this might be related )

But is this scenario really happening ? I don't think libreoffice is daemonizing itself, is it ?

if we have a vulnerability inside libreoffice (I think we have), then isolation of handlers seems very important. When we use cloudooo for erp5 frontend, this is not very important, but in cloudooo.erp5.net we don’t even know what they sent us. maybe use something like sudo and for cloudooo add users "slapos.cloudooo1" "slapos.cloudooo2" ....

Hi @bk I created a test suite CLOUDOOO-19 for this branch.

Test ran here I guess you don't have access to that test result. There is one failure, I don't really see how it's related to these changes.:

testConvertOnlyOfficeToFrom (testX2tServer.TestServer)
Converts xlsx,docx to their y format and y to x ... FAIL

======================================================================
FAIL: testConvertOnlyOfficeToFrom (testX2tServer.TestServer)
Converts xlsx,docx to their y format and y to x
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/slapgrid/slappart9/srv/testnode/cga/soft/cc47468fc64417f3aa754cd22f78fadd/parts/cloudooo-repository/cloudooo/tests/backportUnittest.py", line 136, in run
    testMethod()
  File "/srv/slapgrid/slappart9/srv/testnode/cga/soft/cc47468fc64417f3aa754cd22f78fadd/parts/cloudooo-repository/cloudooo/handler/x2t/tests/testX2tServer.py", line 44, in testConvertOnlyOfficeToFrom
    self.runConversionList(self.ConversionScenarioList())
  File "/srv/slapgrid/slappart9/srv/testnode/cga/soft/cc47468fc64417f3aa754cd22f78fadd/parts/cloudooo-repository/cloudooo/tests/cloudoooTestCase.py", line 153, in runConversionList
    self._testConvertFile(*scenario)
  File "/srv/slapgrid/slappart9/srv/testnode/cga/soft/cc47468fc64417f3aa754cd22f78fadd/parts/cloudooo-repository/cloudooo/tests/cloudoooTestCase.py", line 82, in _testConvertFile
    self.assertEquals(file_type, destination_mimetype)
AssertionError: 'application/zip' != 'application/vnd.openxmlformats-officedocument.spreadsheetml.sheet'

----------------------------------------------------------------------
Ran 1 test in 21.742s

FAILED (failures=1)

For the records, on master branch there was one failure that seem to be introduced in a5157949 and that is fixed in this branch.

======================================================================
FAIL: testWithoutOpenOffice (testOooUnoMimemapper.TestUnoMimeMapper)
Test when the openoffice is stopped
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/srv/slapgrid/slappart5/srv/testnode/bxf/soft/5d7b83809ca61897a76de419dc38cd4c/parts/cloudooo-repository/cloudooo/handler/ooo/tests/testOooUnoMimemapper.py", line 117, in testWithoutOpenOffice
    self.assertTrue(stderr.endswith(error_msg), stderr)
AssertionError: Traceback (most recent call last):
  File "/srv/slapgrid/slappart5/srv/testnode/bxf/soft/5d7b83809ca61897a76de419dc38cd4c/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unomimemapper.py", line 144, in <module>
    main()
  File "/srv/slapgrid/slappart5/srv/testnode/bxf/soft/5d7b83809ca61897a76de419dc38cd4c/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unomimemapper.py", line 136, in main
    mimemapper = UnoMimemapper(hostname, port, uno_path, office_binary_path)
  File "/srv/slapgrid/slappart5/srv/testnode/bxf/soft/5d7b83809ca61897a76de419dc38cd4c/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unomimemapper.py", line 73, in __init__
    office_binary_path)
  File "/srv/slapgrid/slappart5/srv/testnode/bxf/soft/5d7b83809ca61897a76de419dc38cd4c/parts/cloudooo-repository/cloudooo/handler/ooo/helper/helper_util.py", line 33, in getServiceManager
    return uno_connection.ServiceManager
UnboundLocalError: local variable 'uno_connection' referenced before assignment

@bk please write a test to prevent any regression for this issue.

There is one failure, I don't really see how it's related to these changes.:

test ran again and it was OK, cloudooo tests are flaky.

added 5 commits

cedd433c - improve logging
2ad06905 - rework @yusei patch a5157949
722dad78 - close file opened in uno, use only one service_manager by process
0cfb5a16 - stop hanging uno thread
a9ea6f2a - cleanup

Compare with previous version

resolved all discussions

BTW, about the test, do we have a reliable way to trigger the problem ? I had a belief that password protected files where causing cloudooo to hang, but it seems it's able to recover

I played a bit with a test password protected file I created, I see some

2019-05-21 03:51:37 - Cloudooo - DEBUG - OpenOffice 10.0.30.235, 8003 unlocked
2019-05-21 03:51:37 - Cloudooo - ERROR - Traceback (most recent call last):
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/manager.py", line 264, in run_convert
    base_document=True)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/manager.py", line 184, in getFileMetadataItemList
    metadata_dict = handler.getMetadata(base_document)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/x2t/handler.py", line 297, in getMetadata
    .getMetadata(base_document)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/handler.py", line 192, in getMetadata
    stdout, stderr = self._callUnoConverter(*feature_list, **kw)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/handler.py", line 133, in _callUnoConverter
    raise Exception(first_error + second_error)
Exception: Traceback (most recent call last):
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 348, in <module>
    main()
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 324, in main
    uno_path, office_binary_path, refresh)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 87, in __init__
    self._load()
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 159, in _load
    raise AttributeError("This document can not be loaded or is empty")
AttributeError: This document can not be loaded or is empty

error of the second run: Traceback (most recent call last):
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 348, in <module>
    main()
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 324, in main
    uno_path, office_binary_path, refresh)
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 87, in __init__
    self._load()
  File "/srv/slapgrid/slappart8/srv/runner/software/4147f0abe66fea723168ed88eb5628c5/parts/cloudooo-repository/cloudooo/handler/ooo/helper/unoconverter.py", line 159, in _load
    raise AttributeError("This document can not be loaded or is empty")
AttributeError: This document can not be loaded or is empty

in cloudooo log, sometimes some [soffice.bin] <defunct> processes, but they seem to disappear after some time and cloudooo is still accepting connections and performing conversions.

Do we know how to reproduce at this point ?

[ edit: these logs were with an old version of cloudooo ]

I do not know the way guaranteed to catch deadlock in "unoconverter.py". I just caught him at times. But I was lucky and I have a non-standard environment in which this happens every 4 requests. Software started by handlers is very complicated so I don’t think that if we even find a guaranteed way to catch a deadlock, this will prevent us from catch errors like this one.

resolved all discussions

Thanks for explanation. I think in the past there have been a test (not running as part of the test suite) that was converting documents in a loop to make sure that cloudooo (it was oood at that time) still works fine after a few hours of doing conversions for multiple clients. It might be https://lab.nexedi.com/bk/cloudooo/blob/a9ea6f2a59f6fcbc77719eec81ad9ac540b7adb2/cloudooo/handler/ooo/tests/HighTestLoad.py but I'm not sure, I did not follow that.

One small concern I have is that we are now using abort. Isn't it leaving core dump files ? ( in python's test for subprocess abort, they adjust rlimit to prevent this )

Thanks @jerome, it is very important. I'll run the tests. I can make an option in "cloudooo.conf" that will adjust the size of the core dump for all subprocess with the default value 0. For "unoconverter.py" it will always be 0. What do you think?

I feel it's not needed to introduce configurability at this point, simply setting the limit to 0 in unoconverter.py just before calling abort is enough for now:

try:
    # As we will abort ourselves, prevent creation of core dump
    resource.setrlimit(
        resource.RLIMIT_CORE,
        (0,  resource.getrlimit(resource.RLIMIT_CORE)[1]))
except (ValueError, OSError):
    pass (or maybe log the error)
os.abort()

added 16 commits

d1a52dd5 - fix incomplete refactoring in 115e6f1b
8f3d6526 - close file opened in uno, use only one service_manager by process
5102981a - fix deadlock in uno thread
5edc710c - cleanup
6312f7e2 - support python3 in openoffice_tester.py
bbe27cf2 - fix running openoffice_tester.py
a073ec45 - rework @yusei patch a5157949
6a7ccc5b - use connection string as configure interlink between libreoffice and uno client
84721a86 - improve logging
cf4b897b - improve logging
31108c76 - improve logging
a024d621 - fix memory monitor
689dc84e - add disabled logger for tests
684ad8f3 - support libreoffice lockfile
f060f056 - fix start issue
e1b72e0e - correctly terminate libreoffice daemon

Compare with previous version

added 9 commits

467b6b86 - use connection string as configure interlink between libreoffice and uno client
66e7ad71 - improve logging
edacbe10 - improve logging
e4ba9a63 - improve logging
0ec77252 - fix memory monitor
78c4ce1b - add disabled logger for tests
a23689c5 - support libreoffice lockfile
81eba22c - fix start issue
309a413b - correctly terminate libreoffice daemon

Compare with previous version

added 1 commit

2e1b87a9 - speedup starting

Compare with previous version

@jerome , i discovered that the issue of a dead lock occured in all scripts using UNO: office_tester, unoconverter, unomimemapper. I fixed it by senting SIGQUIT to themselves at the end of each script.

openoffice_tester.py have not been working for a long time, because the result of its work was incorrectly interpreted in cloudooo and there were no tests for it. This was the true source the issue which @yusei worked on.

The raise condition in the memory monitor is corrected.

A correct exit from libreOffice is done by sending the terminate command.

Speedup is the result of the correct detection of the demon's running state.

Now pipes are using for connection Uno client and Uno server. This increases the security and a little bit speeds up. Pipes are working well so the remains of using the hostname/port should be removed in tests and in the code.

added 1 commit

bed81b58 - add testOooOfficeTester.py

Compare with previous version

added 1 commit

657457a2 - clenup testFrameWork

Compare with previous version

added 1 commit

dabf6bc3 - add testOooOfficeTester.py

Compare with previous version

added 1 commit

e67d4e97 - add testOooUnoOfficeTester.py

Compare with previous version

added 1 commit

40f9e4ae - add testOooUnoOfficeTester.py

Compare with previous version

added 2 commits

62fa0ab7 - add testOooUnoOfficeTester.py
97b7cb27 - cleanup handlerTestCase.py

Compare with previous version

@romain , I have not invent the test which will guarantee that the issue will not repeat in future. Currently the libreOfficeUnoServer is stopped on base of the timeout, but the issue is that libreOfficeUnoClient hangs up and it's not stopped by cloudooo.

Could you consider:

the timeout for libreOfficeUnoClient in cloudooo and the error logging when the time is exceeded
and the tests which will show that check that client is stopped if the timeout is exceeded.

What do you think? I will add timeout for client and logging and test if you are agree.

Thanks @bk , I took another look but the patch is big and I don't know this so well. Here are a few comments:

@jerome , i discovered that the issue of a dead lock occured in all scripts using UNO: office_tester, unoconverter, unomimemapper. I fixed it by senting SIGQUIT to themselves at the end of each script.

Even now that we properly terminate processes, this "brutal" way of terminating process is still needed ? If at the end of exitOverAbort we just return without the os.kill do you still observe deadlocks ?

Now pipes are using for connection Uno client and Uno server. This increases the security and a little bit speeds up. Pipes are working well so the remains of using the hostname/port should be removed in tests and in the code.

That's interesting. I don't know if there was a reason of using TCP and not pipes.

[ edited for a typo in @bk @ ]

Hi @jerome

I took another look but the patch is big and I don't know this so well.

I'm sorry for rebasing , i was not sure i could manage changes without rebase.

If at the end of exitOverAbort we just return without the os.kill do you still observe deadlocks ?

Unfortunately yes. i just checked that once more and got the deadlocks again. You are right i hoped that the switching from TCP to pipes solved the issue. This is the strace log of unoconverter.py process. 2367 - is the main process, 2381 and 2400 are the threads.

Trace of process 2367 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/uno
strace: Process 2367 attached
futex(0x7f1507a3ea28, FUTEX_WAIT_PRIVATE, 1, NULL```

Trace of process 2381 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/uno
strace: Process 2381 attached
futex(0x7f1507a3ea24, FUTEX_WAIT, 2153644031, NULL

Trace of process 2400 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/uno
strace: Process 2400 attached                                                                                                             
futex(0x7f1506a2eb50, FUTEX_WAIT, 2, NULL

This is the other case.

Trace of process 20998 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/un
strace: Process 20998 attached                                                                                                            
futex(0x7f9ec9ff4a28, FUTEX_WAIT_PRIVATE, 1, NULL

Trace of process 21021 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/un
strace: Process 21021 attached                                                                                                            
futex(0x7f9ec9ff4a24, FUTEX_WAIT, 2174746623, NULL

Trace of process 21022 - /usr/lib/libreoffice/program/python /home/erp5_cloudooo/erp5-buildout/src/cloudooo/cloudooo/handler/ooo/helper/un
strace: Process 21022 attached                                                                                                            
recvfrom(4,

That's interesting. I don't know if there was a reason of using TCP and not pipes.

i'm not sure but basing on the code i think that the TCP using was risen by:

the wrong assumption that cloudooo could not evaluate the state of the subDaemon by the return code. In fact the work state (running/exited) of libreofficeServer can be easily determined by a return code. I corrected that and as a result the libreoffice loading speedups.
libreofficeServer creates a workdir and exits on the fist run in case if its workdir has been absent.
the result of office_tester.py work was wrongly interpreted. Actually office_tester.py didn't work. I fixed this issue.

[ edited for a markdown ]

I'm sorry for rebasing , i was not sure i could manage changes without rebase.

Ah don't worry, I think it's OK to rebase/squash commits because we can use "Compare with previous version" in gitlab. I was just saying that I did not look at all the patch in details.

If at the end of exitOverAbort we just return without the os.kill do you still observe deadlocks ?

Unfortunately yes. i just checked that once more and got the deadlocks again.

I see, thanks for checking this again.

Did you get erp5 test results with your cloudooo branch?

@romain , yes, i got the results: https://nexedijs.erp5.net/#/test_result_module/20190607-49CCD404 . I try to reproduce erp5_officejs_ui_test:* errors on local erp5, but unfortunately without success yet.

You should reduce the number of test to run in your branch, to execute only onlyoffice tests for now.

Do you have any idea where the cause of all those new errors may come from? What happen if you use the original cloudooo?

@romain , yes, i reduced the number of tests erp5!888 .

Do you have any idea where the cause of all those new errors may come from? What happen if you use the original cloudooo?

There was the wrong url of cloudooo server.

That's a good news, and we can see you get the same results than master. Sadly, it also means you get the same error in the spreadsheet app test. Are you sure the spreadsheet error comes from cloudooo? Did you try running this test with a Firefox version 52, as executed by the test bot?

I'm happy that finally i got the same error locally as on master and https://nexedijs.erp5.net/#/test_result_module/20190612-1D24D9F0 . Now i can work on it.

Are you sure the spreadsheet error comes from cloudooo?

I'm sure that this error is not from cloudooo, but before i fixed the previous errors i had not got it. May be the issue was in the order of the running tests, i don't know currently.

Did you try running this test with a Firefox version 52, as executed by the test bot?

Earlier i tried running the test in Firefox version 60 without the error reproduction, now i get the error in Chromium version 73.

nexedi / cloudooo

Fix hangup

Related links

Ready to be merged automatically

Fix hangup

Related links

Check out, review, and merge locally

Ready to be merged automatically