Skip to first unread message
Terence Martin
Aug 4, 2015, 2:54:07 PM8/4/15
to mongoose-users
I'm looking at the code in mongoose that writes to the configured access log file, (function log_access). In the function, fopen() is invoked to open the file, then flockfile() is used to lock the handle while the log line is written, which happens across several calls to fprintf(), followed by an funlockfile() and fclose().
The man page for flockfile() says that this just locks the file handle to make sure that if multiple threads access the handle, their results do not interleave with each other in the output. It also says that this locking has nothing to do with the file locking done by functions like flock(2) and lockf(3).
This means that in cases where there are multiple threads with their own mg_server instance running, which are configured so that they both share the same access log file name, it's possible that both threads will service a request in such a way that their access file entries will overlap in the file. I wrote a simple example of two threads writing to the same file from different file handles and their results definitely interleave with each other.
In practice I don't know how big a deal that might end up being, so I don't know if it's worth it to implement actual file locking, have the function generate the log to a buffer and then write the buffer, etc. I just thought I'd mention it in case I'm misunderstanding or it's a problem that you're not aware of.
I noticed this while checking to see if the file handle was held open or not to know how easy it would be to implement log rolling at the end of each day.
The man page for flockfile() says that this just locks the file handle to make sure that if multiple threads access the handle, their results do not interleave with each other in the output. It also says that this locking has nothing to do with the file locking done by functions like flock(2) and lockf(3).
This means that in cases where there are multiple threads with their own mg_server instance running, which are configured so that they both share the same access log file name, it's possible that both threads will service a request in such a way that their access file entries will overlap in the file. I wrote a simple example of two threads writing to the same file from different file handles and their results definitely interleave with each other.
In practice I don't know how big a deal that might end up being, so I don't know if it's worth it to implement actual file locking, have the function generate the log to a buffer and then write the buffer, etc. I just thought I'd mention it in case I'm misunderstanding or it's a problem that you're not aware of.
I noticed this while checking to see if the file handle was held open or not to know how easy it would be to implement log rolling at the end of each day.
Sergey Lyubka
Aug 14, 2015, 9:32:56 AM8/14/15
to mongoose-users
Thanks Terence.
Honestly, I'd remove the locking alltogether. Normally, if different threads are writing a log file, separate files should be used anyway.
--
You received this message because you are subscribed to the Google Groups "mongoose-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mongoose-user...@googlegroups.com.
To post to this group, send email to mongoos...@googlegroups.com.
Visit this group at http://groups.google.com/group/mongoose-users.
For more options, visit https://groups.google.com/d/optout.
Terence Martin
Aug 14, 2015, 1:30:48 PM8/14/15
to mongoose-users
For my purposes I include the thread number in the access log file name setting since I already had a similar mechanism in place for the hexdump file option for debugging purposes anyway.
I would note though that in the general case I'm not sure how much of a problem it ends up being. Since the code is using buffered I/O and is careful to use fputc to insert the newline at the end (which as far as I can tell does not automatically flush the buffer), the call to fflush() at the end is going to write the entire log line as one chunk of data. So in most cases even if multiple threads hit at the same time the lines end up not overlapping.
Looking back at the test program that I wrote, it wasn't calling fflush() appropriately. So while it did verify that flockfile() does not lock the file but only the FILE * handle, it didn't accurately replicate what was going on.
Of course things like interrupted writes and such might rain on your parade if the kernel can't do the whole write at once and it's probably best to not rely on this anyway.
I would note though that in the general case I'm not sure how much of a problem it ends up being. Since the code is using buffered I/O and is careful to use fputc to insert the newline at the end (which as far as I can tell does not automatically flush the buffer), the call to fflush() at the end is going to write the entire log line as one chunk of data. So in most cases even if multiple threads hit at the same time the lines end up not overlapping.
Looking back at the test program that I wrote, it wasn't calling fflush() appropriately. So while it did verify that flockfile() does not lock the file but only the FILE * handle, it didn't accurately replicate what was going on.
Of course things like interrupted writes and such might rain on your parade if the kernel can't do the whole write at once and it's probably best to not rely on this anyway.
Sergey Lyubka
Aug 15, 2015, 9:35:30 AM8/15/15
to mongoos...@googlegroups.com
Makes sense, thank you!
Reply all
Reply to author
Forward
0 new messages