[sane-devel] [dev] net backend and timing problems? (pretty weird)

Henning Meier-Geinitz henning@meier-geinitz.de
Sun, 9 Sep 2001 14:54:32 +0200


Hi,

On Sat, Sep 08, 2001 at 02:54:49AM +0200, Jochen Eisinger wrote:
> The problem here is, my net backend just doesn't crash, no matter what i
> do :(

CVS-versions of net.c and sanei_wire.c:

Tested with scanimage -T, pnm over localhost. Small files: no problem.
Big files (15 MB in this case): 

[...]
[net] sane_read: next record length=8188 bytes
[net] sane_read: max_length = 32768
[net] sane_read: next record length=7772 bytes
[net] sane_read: max_length = 32768
[net] sane_read: next record length=-1 bytes
[net] sane_cancel
[net] sane_close: handle 0x8051c00
scanimage: stopping scanner... (sig 13)
[net] sane_cancel
scanimage: stopping scanner... (sig 13)
[net] sane_cancel
[...]

Same with SANE 1.0.5.
With xsane, sometimes it works, sometimes I get 
[1]+  Datenübergabe unterbrochen (broken pipe)                xsane

Now with your changes to net.c and sanei_wire.c:
Same symptoms. Here is part of the debug log:

[...]
[net] sane_cloase: net_close
[sanei_wire] sanei_w_call: wire 3 (old status 0)
[sanei_wire] sanei_w_set_dir: wire 3, dir 0
[sanei_wire] flush: wire 3
[sanei_wire] flush: wire flushed
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 0
[sanei_wire] sanei_w_space: sending 0 bytes
[sanei_wire] sanei_w_space: free buffer is now 8192
[sanei_wire] sanei_w_read: done
[sanei_wire] flush: wire flushed
[sanei_wire] sanei_w_set_dir: buffers flushed, direction changed
[sanei_wire] sanei_w_call: sending request
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 3
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 0
[sanei_wire] sanei_w_call: receiving reply
[sanei_wire] sanei_w_set_dir: wire 3, dir 1
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 8184
[sanei_wire] sanei_w_space: sending 8 bytes
scanimage: stopping scanner... (sig 13)
[net] sane_cancel
[sanei_wire] sanei_w_call: wire 3 (old status 0)
[sanei_wire] sanei_w_set_dir: wire 3, dir 0
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 8192
[sanei_wire] sanei_w_space: sending 0 bytes
[sanei_wire] sanei_w_space: free buffer is now 8192
[sanei_wire] sanei_w_read: done
[sanei_wire] flush: wire flushed
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 8192
[sanei_wire] sanei_w_space: sending 0 bytes
[sanei_wire] sanei_w_space: free buffer is now 8192
[sanei_wire] sanei_w_read: done
[sanei_wire] flush: wire flushed
[sanei_wire] sanei_w_set_dir: buffers flushed, direction changed
[sanei_wire] sanei_w_call: sending request
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 8
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 0
[sanei_wire] sanei_w_call: receiving reply
[sanei_wire] sanei_w_set_dir: wire 3, dir 1
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 8184
[sanei_wire] sanei_w_space: sending 8 bytes
[sanei_wire] sanei_w_space: write failed (32)
[sanei_wire] flush: error status 32
[sanei_wire] flush: wire flushed
[sanei_wire] flush: wire 3
[sanei_wire] flush: error status 32
[sanei_wire] flush: wire flushed
[sanei_wire] sanei_w_set_dir: buffers flushed, direction changed
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_space: wire is in invalid state 32
[sanei_wire] sanei_w_word: value = 8
[sanei_wire] sanei_w_call: error status 32
[net] do_cancel: 0x8051c00
scanimage: stopping scanner... (sig 13)
[net] sane_cancel
[sanei_wire] sanei_w_call: wire 3 (old status 32)
[sanei_wire] sanei_w_set_dir: wire 3, dir 0
[sanei_wire] flush: wire 3
[sanei_wire] flush: wire flushed
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 0
[sanei_wire] sanei_w_space: sending 0 bytes
[sanei_wire] sanei_w_space: free buffer is now 8192
[sanei_wire] sanei_w_read: done
[sanei_wire] flush: wire flushed
[sanei_wire] sanei_w_set_dir: buffers flushed, direction changed
[sanei_wire] sanei_w_call: sending request
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 8
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_read: done
[sanei_wire] sanei_w_word: value = 0
[sanei_wire] sanei_w_call: receiving reply
[sanei_wire] sanei_w_set_dir: wire 3, dir 1
[sanei_wire] flush: wire 3
[sanei_wire] sanei_w_space: 8193 bytes for wire 3
[sanei_wire] sanei_w_space: this won't fit in the buffer anyways :( ... could be flush() though
[sanei_wire] sanei_w_space: free buffer size is 8184
[sanei_wire] sanei_w_space: sending 8 bytes
[sanei_wire] sanei_w_space: write failed (32)
[sanei_wire] flush: error status 32
[sanei_wire] flush: wire flushed
[sanei_wire] flush: wire 3
[sanei_wire] flush: error status 32
[sanei_wire] flush: wire flushed
[sanei_wire] sanei_w_set_dir: buffers flushed, direction changed
[sanei_wire] sanei_w_word: wire 3
[sanei_wire] sanei_w_space: 4 bytes for wire 3
[sanei_wire] sanei_w_space: wire is in invalid state 32
[sanei_wire] sanei_w_word: value = 8
[sanei_wire] sanei_w_call: error status 32
[net] do_cancel: 0x8051c00
scanimage: stopping scanner... (sig 13)
[net] sane_cancel
[...]

Repeated over and over again untill I sigkill scanimage.
No (unusual) messages in syslog. With saned -D128, the problem doesn't
always occur. When it's there, I get something like the following as
the last messages in syslog:

Sep  9 14:50:26 hmg1 saned[4440]: do_scan: read 8188 bytes from scanner 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: wrote 8192 bytes to client 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: read 8188 bytes from scanner 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: wrote 8192 bytes to client 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: read 8188 bytes from scanner 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: wrote 8192 bytes to client 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: read 7772 bytes from scanner 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: wrote 7776 bytes to client 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: read 7772 bytes from scanner 
Sep  9 14:50:26 hmg1 saned[4440]: do_scan: wrote 416 bytes to client 
Sep  9 14:50:26 hmg1 saned[4440]: received signal 13 
Sep  9 14:50:26 hmg1 saned[4440]: exiting 

Bye,
  Henning