Error when printing screen (but document printed anyway)

[Borja López Soilán (NeoPolus)]

When printing a record, using "print screen", from Koo an error message appears, though the printing (PDF) completes.

The error displayed is the next one:

"MSG [Errno 4] Llamada de interrupción de sistema: [Errno 4] Llamada de interrupción de sistema"

and when I click on OK I get the next trace:

"
Traceback (most recent call last):
  File "/usr/local/lib/python2.6/dist-packages/Koo/Screen/Screen.py", line 230, in triggerAction
    self.reload()
  File "/usr/local/lib/python2.6/dist-packages/Koo/Screen/Screen.py", line 586, in reload
    self.currentRecord().reload()
  File "/usr/local/lib/python2.6/dist-packages/Koo/Model/Record.py", line 381, in reload
    res = self.rpc.read([self.id], self.group.allFieldNames(), c)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 579, in __call__
    return session.execute('/object', 'execute', self.object, self.func, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 419, in execute
    return self.call(obj, method, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 407, in call
    value = self.connection.call(obj, method, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 214, in call
    raise RpcProtocolException( err )
Koo.Rpc.Rpc.RpcProtocolException: [Errno 4] Llamada de interrupción de sistema
"

Printing the same records ("print screen" again) from the GTK Client works. Also no errors are displayed when printing reports instead of using 'print screen'.

Note: Tested on Koo revno 1176; using OpenObject-Server revno 1877.

[Borja López Soilán (NeoPolus) (borjals)]

It seems the error message might appear also when printing some reports (ODT file). When it happens, the next stacktrace is shown on the server side:

----------------------------------------
Exception happened during processing of request from ('127.0.0.1', 53681)
Traceback (most recent call last):
  File "/usr/lib/python2.5/SocketServer.py", line 464, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python2.5/SocketServer.py", line 254, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python2.5/SocketServer.py", line 522, in __init__
    self.handle()
  File "/usr/lib/python2.5/BaseHTTPServer.py", line 316, in handle
    self.handle_one_request()
  File "/usr/lib/python2.5/BaseHTTPServer.py", line 310, in handle_one_request
    method()
  File "/usr/lib/python2.5/SimpleXMLRPCServer.py", line 477, in do_POST
    self.send_response(200)
  File "/usr/lib/python2.5/BaseHTTPServer.py", line 370, in send_response
    self.send_header('Server', self.version_string())
  File "/usr/lib/python2.5/BaseHTTPServer.py", line 376, in send_header
    self.wfile.write("%s: %s\r\n" % (keyword, value))
  File "/usr/lib/python2.5/socket.py", line 274, in write
    self.flush()
  File "/usr/lib/python2.5/socket.py", line 261, in flush
    self._sock.sendall(buffer)
error: (32, 'Tuber\xc3\xada rota')
----------------------------------------

[Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan)]

A Dimecres, 18 de novembre de 2009, Borja López Soilán (Pexego) va escriure:
> It seems the error message might appear also when printing some reports
> (ODT file). When it happens, the next stacktrace is shown on the server
> side:
>
> ----------------------------------------
> Exception happened during processing of request from ('127.0.0.1', 53681)
> Traceback (most recent call last):
> File "/usr/lib/python2.5/SocketServer.py", line 464, in
> process_request_thread self.finish_request(request, client_address)
> File "/usr/lib/python2.5/SocketServer.py", line 254, in finish_request
> self.RequestHandlerClass(request, client_address, self)
> File "/usr/lib/python2.5/SocketServer.py", line 522, in __init__
> self.handle()
> File "/usr/lib/python2.5/BaseHTTPServer.py", line 316, in handle
> self.handle_one_request()
> File "/usr/lib/python2.5/BaseHTTPServer.py", line 310, in
> handle_one_request method()
> File "/usr/lib/python2.5/SimpleXMLRPCServer.py", line 477, in do_POST
> self.send_response(200)
> File "/usr/lib/python2.5/BaseHTTPServer.py", line 370, in send_response
> self.send_header('Server', self.version_string())
> File "/usr/lib/python2.5/BaseHTTPServer.py", line 376, in send_header
> self.wfile.write("%s: %s\r\n" % (keyword, value))
> File "/usr/lib/python2.5/socket.py", line 274, in write
> self.flush()
> File "/usr/lib/python2.5/socket.py", line 261, in flush
> self._sock.sendall(buffer)
> error: (32, 'Tuber\xc3\xada rota')
> ----------------------------------------
>

It's pretty strange. Can you please try with other protocols? Maybe with pyro?

--
Albert Cervera i Areny
http://www.NaN-tic.com
Mòbil: [phone]

[Borja López Soilán (NeoPolus) (borjals)]

With Pyro it works (and does work faster by the way).

Using Net-RPC (instead of XML-RPC) it fails like this:
"MSG (4, 'Llamada de interrupci\xc3\xb3n de sistema'): (4, 'Llamada de interrupci\xc3\xb3n de sistema')"
"
Traceback (most recent call last):
  File "/usr/local/lib/python2.6/dist-packages/Koo/Dialogs/FormWidget.py", line 427, in updateStatus
    if self.model and self.screen.currentRecord() and self.screen.currentRecord().id:
  File "/usr/local/lib/python2.6/dist-packages/Koo/Screen/Screen.py", line 321, in currentRecord
    return self.group.modelByIndex( self._currentRecordPosition )
  File "/usr/local/lib/python2.6/dist-packages/Koo/Model/Group.py", line 547, in modelByIndex
    self.ensureModelLoaded(record)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Model/Group.py", line 627, in ensureModelLoaded
    values = self.rpc.read(queryIds, missingFields, c)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 579, in __call__
    return session.execute('/object', 'execute', self.object, self.func, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 419, in execute
    return self.call(obj, method, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 407, in call
    value = self.connection.call(obj, method, *args)
  File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 189, in call
    raise RpcProtocolException( unicode(err) )
Koo.Rpc.Rpc.RpcProtocolException: (4, 'Llamada de interrupci\xc3\xb3n de sistema')
"

[Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan)]

Could it, in some way be a problem with your system? Can you try it in another
machine? Just to discard things...

A Dimecres, 18 de novembre de 2009, Borja López Soilán (Pexego) va escriure:
> With Pyro it works (and does work faster by the way).
>
> Using Net-RPC (instead of XML-RPC) it fails like this:
> "MSG (4, 'Llamada de interrupci\xc3\xb3n de sistema'): (4, 'Llamada de
> interrupci\xc3\xb3n de sistema')" "
> Traceback (most recent call last):
> File "/usr/local/lib/python2.6/dist-packages/Koo/Dialogs/FormWidget.py",
> line 427, in updateStatus if self.model and self.screen.currentRecord()
> and self.screen.currentRecord().id: File
> "/usr/local/lib/python2.6/dist-packages/Koo/Screen/Screen.py", line 321,
> in currentRecord return self.group.modelByIndex(
> self._currentRecordPosition )
> File "/usr/local/lib/python2.6/dist-packages/Koo/Model/Group.py", line
> 547, in modelByIndex self.ensureModelLoaded(record)
> File "/usr/local/lib/python2.6/dist-packages/Koo/Model/Group.py", line
> 627, in ensureModelLoaded values = self.rpc.read(queryIds, missingFields,
> c)
> File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 579,
> in __call__ return session.execute('/object', 'execute', self.object,
> self.func, *args) File
> "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 419, in
> execute return self.call(obj, method, *args)
> File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 407,
> in call value = self.connection.call(obj, method, *args)
> File "/usr/local/lib/python2.6/dist-packages/Koo/Rpc/Rpc.py", line 189,
> in call raise RpcProtocolException( unicode(err) )
> Koo.Rpc.Rpc.RpcProtocolException: (4, 'Llamada de interrupci\xc3\xb3n de
> sistema') "
>

--
Albert Cervera i Areny
http://www.NaN-tic.com
Mòbil: [phone]

[Borja López Soilán (NeoPolus) (borjals)]

Hi Albert,

It's not a problema with my system (Linux Mint 7 32bit; python 2.6). Yesterday we reproduced the same problem on one Ubuntu 9.10 64bit (python 2.6): About 1/4 of the times we printed something, the error RpcProtocolException message would show up just after the PDF generation.

[Borja López Soilán (NeoPolus) (borjals)]

In the end it seems some kind of race condition on Printer.printData:

I tried to debug that method and found that, when I ran it step by step it would not fail. After some trial and error, I found that, if I set a break point on the "Semantic.addInformationToFile( fileName, model, ids )" call, the exception won't happen.
Even more, adding a simple "import time; time.sleep(1)" line between the Printer.printFile and Semantic.addInformationToFile calls would prevent the exceptions.

So my guess is:
  - On linux Printer.printFile calls "lpr" or "xdg-open" to print or open (preview) the file. Any of them will lock the file for reading.
  - Semantic.addInformationToFile tries to open the file for writing, but the file may still/already be locked for reading (at least on Core2Duo systems).

If we move the Semantic.addInformationToFile before the Printer.printFile, the problem is avoided.

[Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan)]

I must admit that I don't fully understand the problem. Files are not locked by default on Linux so it should not be a locking issue. Also the exception is produced in the RPC call produced by FormWidget, that is, probably when the current view is refreshed just after printing (and after semantic information has been added).

I have, however, applied your patch in r1215 and I'm closing the bug as it seems to solve the problem for you.

[Borja López Soilán (NeoPolus) (borjals)]

Sorry, I though that the patch did solve the problem, but it did not! (though it did improve things a bit: errors where not as frequent).

And you where right, the race condition is not caused by the file being locked: Using the original printData (with Printer.printFile before Semantic.addInformationToFile), but adding a time.sleep(1) in the updateStatus avoids the race condition too.

The race condition has something to do with the underlying socket of the Net-RPC connection.

I'm currently using Net-RPC, and I could trace down the problem to the SocketConnection.call: tiny_socket.myreceive ("s.myreceive()") is raising a socket.error with errno.EINTR value (4).

If I switch to XML-RPC the problem is less frequent, but persist; the main diference is that this time the OpenERP server logs this:
"
Exception happened during processing of request from ('127.0.0.1', 39514)
Traceback (most recent call last):
  File "/usr/lib/python2.6/SocketServer.py", line 558, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python2.6/SocketServer.py", line 320, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python2.6/SocketServer.py", line 615, in __init__
    self.handle()
  File "/usr/lib/python2.6/BaseHTTPServer.py", line 329, in handle
    self.handle_one_request()
  File "/usr/lib/python2.6/BaseHTTPServer.py", line 323, in handle_one_request
    method()
  File "/usr/lib/python2.6/SimpleXMLRPCServer.py", line 487, in do_POST
    self.send_response(200)
  File "/usr/lib/python2.6/BaseHTTPServer.py", line 384, in send_response
    self.send_header('Server', self.version_string())
  File "/usr/lib/python2.6/BaseHTTPServer.py", line 390, in send_header
    self.wfile.write("%s: %s\r\n" % (keyword, value))
  File "/usr/lib/python2.6/socket.py", line 297, in write
    self.flush()
  File "/usr/lib/python2.6/socket.py", line 284, in flush
    self._sock.sendall(buffer)
error: [Errno 32] Tubería rota
"

So in the end, it seems that it is a problem (or feature) of Python's socket module not hiding or handling by himself some 'exceptions' caused by system signals: http://utcc.utoronto.ca/~cks/space/blog/python/PythonEINTR

Now the questions are:
  - Why is the Koo thread receiving a signal (which is interrupting the socket calls) when 'printing'?
  - Does this happen only when 'printing' or a signal may be received anytime? (and this the socket communication may crash anytime)
  - As this tiny_socket.py seems to be the a copy of the one OpenERP server uses... does that mean that OpenERP server is also susceptible to EINTR problems?

[Borja López Soilán (NeoPolus) (borjals)]

I just did debug Koo using strace. This is what happens when I try to 'print' from Koo:
"
$ strace -p 24648 -e trace=signal
Process 24648 attached - interrupt to quit
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
sigreturn() = ? (mask now [])
"

As you can see the process received three signals: too ignored SIGPIPE signals, and one unhandled SIGCHLD. This last unhandled signal is the cause of the Koo "Llamada de interrupción de sistema" exception.

That SIGCHLD signal is sent by the sub-process created by spawnlp; either in Common.openFile if using print preview: "os.spawnlp(os.P_NOWAIT, 'xdg-open', 'xdg-open', fileName)", or in Printer.sendToPrinter if not using print preview: "os.spawnlp(os.P_NOWAIT, 'lpr', 'lpr', fileName)"

If the spawned subprocess ends while Koo is doing some I/O call (like the socket.recv), the I/O will fail with a EINTR* error (Python does not handle EINTR errors!). The I/O call should be retried then, but neither Python nor the current tiny_socket do that, they just raise up the exception.

* EINTR means "The recv() function was interrupted by a signal that was caught, before any data was available." / "A signal interrupted send() before any data was transmitted." (http://www.opengroup.org/onlinepubs/000095399/functions/recv.html) so the calls can be safely retried.

I'm attaching a patched tiny_socket.py file, that handles EINTR, retrying the recv/send calls if they get interrupted by any signal :)

[* By the way, some of the server modules [like jasper_reports] use spawnlp too, so they may cause OpenERP server to receive SIGCHLD signals too... :( ]

[Albert Cervera i Areny - http://www.NaN-tic.com (albert-nan)]

You could try launching the server in rpc_debug mode and see what's receiving
and sending. That would point us to the exact server call that is giving the
exception and the parameters it's receiving.

A Dimarts, 29 de desembre de 2009, Borja López Soilán (Pexego) va escriure:
> Sorry, I though that the patch did solve the problem, but it did not!
> (though it did improve things a bit: errors where not as frequent).
>
> And you where right, the race condition is not caused by the file being
> locked: Using the original printData (with Printer.printFile before
> Semantic.addInformationToFile), but adding a time.sleep(1) in the
> updateStatus avoids the race condition too.
>
> The race condition has something to do with the underlying socket of the
> Net-RPC connection.
>
> I'm currently using Net-RPC, and I could trace down the problem to the
> SocketConnection.call: tiny_socket.myreceive ("s.myreceive()") is
> raising a socket.error with errno.EINTR value (4).
>
> If I switch to XML-RPC the problem is less frequent, but persist; the main
> diference is that this time the OpenERP server logs this: "
> Exception happened during processing of request from ('127.0.0.1', 39514)
> Traceback (most recent call last):
> File "/usr/lib/python2.6/SocketServer.py", line 558, in
> process_request_thread self.finish_request(request, client_address)
> File "/usr/lib/python2.6/SocketServer.py", line 320, in finish_request
> self.RequestHandlerClass(request, client_address, self)
> File "/usr/lib/python2.6/SocketServer.py", line 615, in __init__
> self.handle()
> File "/usr/lib/python2.6/BaseHTTPServer.py", line 329, in handle
> self.handle_one_request()
> File "/usr/lib/python2.6/BaseHTTPServer.py", line 323, in
> handle_one_request method()
> File "/usr/lib/python2.6/SimpleXMLRPCServer.py", line 487, in do_POST
> self.send_response(200)
> File "/usr/lib/python2.6/BaseHTTPServer.py", line 384, in send_response
> self.send_header('Server', self.version_string())
> File "/usr/lib/python2.6/BaseHTTPServer.py", line 390, in send_header
> self.wfile.write("%s: %s\r\n" % (keyword, value))
> File "/usr/lib/python2.6/socket.py", line 297, in write
> self.flush()
> File "/usr/lib/python2.6/socket.py", line 284, in flush
> self._sock.sendall(buffer)
> error: [Errno 32] Tubería rota
> "
>
> So in the end, it seems that it is a problem (or feature) of Python's
> socket module not hiding or handling by himself some 'exceptions' caused
> by system signals:
> http://utcc.utoronto.ca/~cks/space/blog/python/PythonEINTR
>
>
> Now the questions are:
> - Why is the Koo thread receiving a signal (which is interrupting the
> socket calls) when 'printing'? - Does this happen only when 'printing' or
> a signal may be received anytime? (and this the socket communication may
> crash anytime) - As this tiny_socket.py seems to be the a copy of the one
> OpenERP server uses... does that mean that OpenERP server is also
> susceptible to EINTR problems?
>

--
Albert Cervera i Areny
http://www.NaN-tic.com
Mòbil: [phone]

[Borja López Soilán (NeoPolus) (borjals)]

Albert, when I enable the rpc_debug ("--log-level=rpc_debug") seems that the timing is no longer 'the right one' so it does not run into the race condition (the SIGCHLD signal no longer arrives while Koo is reading data from the socket).

By the way, I checked the OpenERP server, and it is vulnerable too (it may receive SIGCHLD signals causing EINTR errors on tiny_socket that aren't propertly handled).