File I/O from threads

[Maarten Mortier]

Hi, I was writing a quick Relay class and ran into a problem.
Objects of this class act between two ports and log every TCP/IP that is
sent between those ports - according to a specific protocol (in this
simple example the first 8 characters contain the length of the data
that will follow)

These are the important methods of the class. All objects are local to
the object and not shared between other objects.


def start
@server = TCPServer.new(l_h, l_p)
@client = TCPSocket.new(r_h, r_p)

loop do
Thread.start(@server.accept) do |s|
# handshake(s)
client_to_server(s)
server_to_client(s)
end
end
end

def client_to_server(s)
Thread.new do
loop do
len = @client.recv(8)
msg = @client.recv(len.to_i)
@logfile.puts("Received " + msg)
s.write(len)
s.write(msg)
end
end
end

def server_to_client(s)
Thread.new do
loop do
len = s.recv(8)
msg = s.recv(len.to_i)
@logfile.puts("Sent " + msg)
@client.write(len)
@client.write(msg)
end
end
end


My problem is that the file operations (@logfile.puts) are not performed
immediately. When I check the file while communication is passing by, it
is incomplete, sometimes even empty. Only when I kill the connection
contained in @server.accept is the file properly flushed and is all
traffic put into it.
I don't understand why this happens. Why does @logfile.puts not happen
immediately while @client.write and s.write do?
I can't see why this would have anything to do with thread safety.

Putting a mutex lock/unlock around the file operation didn't really do
anything (I didn't really expect that to work either)

Can anybody tell me what is happening here?

 

[Robert Klemme]

Hi, I was writing a quick Relay class and ran into a problem.
Objects of this class act between two ports and log every TCP/IP that is
sent between those ports - according to a specific protocol (in this
simple example the first 8 characters contain the length of the data
that will follow)

These are the important methods of the class. All objects are local to
the object and not shared between other objects.


def start
@server = TCPServer.new(l_h, l_p)
@client = TCPSocket.new(r_h, r_p)

loop do
Thread.start(@server.accept) do |s|
# handshake(s)
client_to_server(s)
server_to_client(s)
end
end
end

def client_to_server(s)
Thread.new do
loop do
len = @client.recv(8)
msg = @client.recv(len.to_i)
@logfile.puts("Received " + msg)
s.write(len)
s.write(msg)
end
end
end

def server_to_client(s)
Thread.new do
loop do
len = s.recv(8)
msg = s.recv(len.to_i)
@logfile.puts("Sent " + msg)
@client.write(len)
@client.write(msg)
end
end
end


My problem is that the file operations (@logfile.puts) are not performed
immediately. When I check the file while communication is passing by, it
is incomplete, sometimes even empty. Only when I kill the connection
contained in @server.accept is the file properly flushed and is all
traffic put into it.
I don't understand why this happens. Why does @logfile.puts not happen
immediately while @client.write and s.write do?
I can't see why this would have anything to do with thread safety.

Putting a mutex lock/unlock around the file operation didn't really do
anything (I didn't really expect that to work either)

Can anybody tell me what is happening here?

You see the effect of IO buffering which indeed does not have anything
to do with multi threading. You basically have two options to remedy that

1. use @client.sync = true for automatic flushing after every write
operation

2. manually invoke #flush

Independent from that you should take measures to make writing to the
logfile thread safe. One option would be to have a reserved writer
thread which pulls log messages from a Queue and writes them to the file.

Another alternative is your approach (synchronization).

Kind regards

robert

 

[Maarten Mortier]

You see the effect of IO buffering

Thanks!

Maarten