On 07/04/14 11:32, Phil Mayers wrote:

On 07/04/14 11:07, Arran Cudbard-Bell wrote:

...

20 internet points if you can spot the issue...

Wack wack oops.

Good old fnctl locking! Many thanks to AT&T for gifting us their behaviour...

Maybe it should be switched to flock() given FreeRadius is threaded? IIRC the only external programs (that come with the server) relying on the locking mode are radsqlrelay and radrelay?

Oh dear. Seems I might have instigated this: http://lists.freeradius.org/mailman/private/freeradius-devel/2012-December/0... ...which triggered: https://github.com/FreeRADIUS/freeradius-server/commit/582852042b4aa6810a683... Oops... Sorry!

On 7 Apr 2014, at 11:50, Matthew Newton <mcn4@LEICESTER.AC.UK> wrote:

On Mon, Apr 07, 2014 at 11:39:59AM +0100, Phil Mayers wrote:

...

http://lists.freeradius.org/mailman/private/freeradius-devel/2012-December/0...

Any chance we can turn the passwords off for this again? This link is inaccessible for most on this list, and just annoying for the rest of us!

Huh, i'm not sure there's restrictions on who can view the archive... I didn't have to log in to view anything, weird. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

On 07/04/14 11:50, Matthew Newton wrote:

On Mon, Apr 07, 2014 at 11:39:59AM +0100, Phil Mayers wrote:

...

http://lists.freeradius.org/mailman/private/freeradius-devel/2012-December/0...

Any chance we can turn the passwords off for this again? This link is inaccessible for most on this list, and just annoying for the rest of us!

And the -users list in fact? Freeradius-Users Archives. (The current archive is only available to the list members.) Annoying...

On Wed, Apr 09, 2014 at 04:08:27PM -0400, Alan DeKok wrote:

Phil Mayers wrote:

...

Freeradius-Users Archives. (The current archive is only available to the list members.)

I've made both of the archives public again.

Much better - thanks!

The original reason for privacy was someone who requested that their posts be removed from the archives. I think a good answer is "no".

I just searched Google and realised it's actually public on other sites anyway, so there's little point even removing an individual message. Cheers, Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>

On 7 Apr 2014, at 12:33, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:

On 7 Apr 2014, at 11:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:

...

On 07/04/14 11:32, Phil Mayers wrote:

...

On 07/04/14 11:07, Arran Cudbard-Bell wrote:

...

20 internet points if you can spot the issue...

Wack wack oops.

Good old fnctl locking! Many thanks to AT&T for gifting us their behaviour...

Maybe it should be switched to flock() given FreeRadius is threaded? IIRC the only external programs (that come with the server) relying on the locking mode are radsqlrelay and radrelay?

Oh dear. Seems I might have instigated this:

http://lists.freeradius.org/mailman/private/freeradius-devel/2012-December/0...

...which triggered:

https://github.com/FreeRADIUS/freeradius-server/commit/582852042b4aa6810a683...

Oops... Sorry!

Ha, all your fault, all your fault :)

flock is sometimes just a wrapper around fcntl so may be just as broken, at least by moving to something we know is broken in terms of reflecting lock states internally, it means that we'll account for it in the code.

Anyway, I've just added a mutex around the writes for now.

I spent a few days investigating locking schemes on *NIX a while back and , came to the conclusion the only sane way of implementing a sane file locking scheme is to have a structure in the server core which holds all the currently open file handles, and their lock states.

The entries for the files would reflect the locking state presented to other processes with fcntl.

Entries would should probably persist after whatever needed the lock has released it, and expire out after a period of inactivity, else will have to initialise a mutex on every file access.

Just checked, and all the other modules which use rad_lockfd are marked as THREAD_UNSAFE. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

Phil Mayers wrote:

Huh, I didn't realise rlm_detail was thread-unsafe; I was wondering why it wasn't affected.

That's historical, and due to the locking APIs being terrible. Alan DeKok.

Hi, there was no real "it's fixed" conclusion yesterday, was there? I.e. could you point me to a commit to cherry-pick? If not... here's a really simple and stupid suggestion (from someone who didn't write C/C++ since a decade!):

if ((rad_lockfd(fd, len + 2) < 0) || (write(fd, query, len) < 0) || (write(fd, ";\n", 2) < 0)) {

Since the main problem is that the ; and queries somehow get mixed - would not a *single* write that combines the two write()s fix that? I'm thinking of: ... || (write(fd, query + ";\n", len + 2) < 0) ... Maybe I'm too naive ... Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66

On 08/04/14 09:12, Arran Cudbard-Bell wrote:

There is that other multi variable version of write, but i'm not sure if it's guaranteed to be atomic.

Plain old write() is not guaranteed to be atomic, let alone writev(). Signals can interrupt writing and necessitate a retry. Any write() needs to be wrapped in a loop to ensure the entire buffer was handled. IIRC there are some weak guarantees in which a write() will tend to be atomic - something related to PIPE_BUF even though it's a plain file? - which is why rlm_linelog doesn't suffer interleaving problems (much?).

Hi,

Oh, sorry... It's fixed!

...

I.e. could you point me to a commit to cherry-pick?

https://github.com/FreeRADIUS/freeradius-server/commit/a2a04cd15bc3886ceb7d1...

I cherry-picked this one and recompiled. Didn't truly solve the issue. I have apporx 5 writes into the file per second, and got garbled statements 2-3 times a day after the fix. My colleague Bruno investigated this further. It looks like the fcntl() locking doesn't catch all corner cases. He writes: c.f.: man 2 fcntl As well as being removed by an explicit F_UNLCK, record locks are automatically released when the process terminates or if it closes any file descriptor referring to a file on which locks are held. This is bad: it means that a process can lose the locks on a file like /etc/passwd or /etc/mtab when for some reason a library function decides to open, read and close it. This means that rad_lockfd() might possibly have no effect: -thread1- -thread2- -thread3- open(logfile) . . rad_lockfd() . . write(query) . . write(";\n") . . . open(logfile) open(logfile) . rad_lockfd() . . rad_lockfd( . write(query) . close() . ) . . write(query) . write(";\n") write(";\n") . close() close() We think we fixed it locally (Bruno's patch attached) by combining both strings into one write() as I suggested earlier. We're aware that this is also no /guarantee/ that the string is written atomically, but the cases where it's not are limited to corner conditions (out of memory, thrashing, ...) and so shouldn't occur during normal operations. Take the patch or leave it, it does seem to work for us :-) Stefan

...

If not... here's a really simple and stupid suggestion (from someone who didn't write C/C++ since a decade!):

...

if ((rad_lockfd(fd, len + 2) < 0) || (write(fd, query, len) < 0) || (write(fd, ";\n", 2) < 0)) {

Since the main problem is that the ; and queries somehow get mixed - would not a *single* write that combines the two write()s fix that? I'm thinking of:

... || (write(fd, query + ";\n", len + 2) < 0) ...

Maybe I'm too naive ...

Well, it'd involve allocing an intermediary buffer as you can't do string concatenation like that in C.

There is that other multi variable version of write, but i'm not sure if it's guaranteed to be atomic.

Maybe Alan can comment, he seems to have an encyclopaedic knowledge of C pitfalls :)

-Arran

Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team

FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66

On 10 Apr 2014, at 12:45, Stefan Winter <stefan.winter@restena.lu> wrote:

Hi,

...

Oh, sorry... It's fixed!

...

I.e. could you point me to a commit to cherry-pick?

https://github.com/FreeRADIUS/freeradius-server/commit/a2a04cd15bc3886ceb7d1...

I cherry-picked this one and recompiled. Didn't truly solve the issue.

I have apporx 5 writes into the file per second, and got garbled statements 2-3 times a day after the fix.

My colleague Bruno investigated this further. It looks like the fcntl() locking doesn't catch all corner cases. He writes:

c.f.: man 2 fcntl

As well as being removed by an explicit F_UNLCK, record locks are automatically released when the process terminates or if it closes any file descriptor referring to a file on which locks are held. This is bad: it means that a process can lose the locks on a file like /etc/passwd or /etc/mtab when for some reason a library function decides to open, read and close it.

This means that rad_lockfd() might possibly have no effect:

-thread1- -thread2- -thread3- open(logfile) . . rad_lockfd() . . write(query) . . write(";\n") . . . open(logfile) open(logfile) . rad_lockfd() . . rad_lockfd( . write(query) . close() . ) . . write(query) . write(";\n") write(";\n") . close() close()

We think we fixed it locally (Bruno's patch attached) by combining both strings into one write() as I suggested earlier.

We're aware that this is also no /guarantee/ that the string is written atomically, but the cases where it's not are limited to corner conditions (out of memory, thrashing, ...) and so shouldn't occur during normal operations.

Take the patch or leave it, it does seem to work for us :-)

It's quite inefficient, you have to strdup the entire buffer just to add two characters. fcntl locks are completely irrelevant in this case, there should now be a mutex around that call preventing multiple writes to the file by different threads... fcntl locks are not mirrored back to threads within the same process, so if one thread locks the file, and another thread attempts to acquire the lock it will succeed. They're not at all useful for synchronisation within a process, only for notifying other processes that the file, or certain areas of the file, are locked. Please check the correct fix was cherry picked. Note: If you're using multiple instances of rlm_sql, and having them all log to the same log file, you'll still experience issues. The only fix for this is some kind of central locking API within the server core. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

Hi,

We can't help it if *another* module opens && closes the same file. But that's a configuration error. Module A and module B shouldn't be writing to the same file.

Whoa. Why would that be a configuration error? I have multiple instances of rlm_sql_null, all writing different SQL statements, and all writing into the same file for forwarding to the SQL server by radsqlrelay. This has worked for years with rlm_... whatever it was called in v2 that wrote SQL to file. If that's a config error now, I'll have to do some serious re-org of my config.

Thread access to the file descriptor is protected by a mutex. So only one thread at a time will be using the file descriptor.

The hope is that this change avoids all of the POSIX locking issues you've seen. It also re-uses FDs, which should be faster than re-opening the file every time.

Let me know if there are any issues. It passes my tests, but I didn't try hammering it under load.

The 3.0.2 with our local patch runs fine, and I can't spare much time on anything but heartbleed these days. Maybe I'll try 3.0.x later; for now, I'm happy that nothing distracts me. Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66

On 11/04/14 12:24, Alan DeKok wrote:

Stefan Winter wrote:

...

Whoa. Why would that be a configuration error?

Because we can't guarantee that the writes occur properly.

...

I have multiple instances of rlm_sql_null, all writing different SQL statements, and all writing into the same file for forwarding to the SQL server by radsqlrelay.

Which doesn't work with POSIX locks, as you pointed out. It might work accidentally, but different threads writing to the same file will cause problems. One thread closing a file descriptor will cause another thread to magically lose its lock.

I think it's important to note this *will* be working for 2.2.x on Linux because the locking #ifdef will end up using flock() which has saner, per-fd semantics. That said: I don't see why your changes would cause semantic problems here. Since all rlm_sql instances use the logging api, surely they'll all interact just fine with >1 instance writing to the same name? I am rather concerned about the locking overhead of the new approach though; my gut feeling tells me a double mutex acquire/release will likely be more expensive than the open()/close() calls, but hopefully I'm wrong.

On 11 Apr 2014, at 10:26, Alan DeKok <aland@deployingradius.com> wrote:

Phil Mayers wrote:

...

I think it's important to note this *will* be working for 2.2.x on Linux because the locking #ifdef will end up using flock() which has saner, per-fd semantics.

I don't recall why that was changed. There was a reason, right?

Not in any way portable? -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

On 11/04/14 15:47, Alan DeKok wrote:

Arran Cudbard-Bell wrote:

...

...

I don't recall why that was changed. There was a reason, right?

Not in any way portable?

Maybe... but it does work somewhere. It may be useful to use flock() where it works. i.e. Linux. That way the systems with sane APIs can get the benefit, and everyone else gets "best effort".

Bear in mind flock() has it's own set of insanities - locks are inherited across fork *and* exec, amongst others. But it's at least consistent with what 2.x has done for years ;o) Assuming it gets accepted and BSD/MacOS follow suit, F_SETLKP should fix fcntl() locking and this should, finally, go away.

On 11 Apr 2014, at 10:26, Alan DeKok <aland@deployingradius.com> wrote:

Phil Mayers wrote:

...

I think it's important to note this *will* be working for 2.2.x on Linux because the locking #ifdef will end up using flock() which has saner, per-fd semantics.

I don't recall why that was changed. There was a reason, right?

flock not being portable? Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

On 11 Apr 2014, at 07:24, Alan DeKok <aland@deployingradius.com> wrote:

Stefan Winter wrote:

...

Whoa. Why would that be a configuration error?

Because we can't guarantee that the writes occur properly.

...

I have multiple instances of rlm_sql_null, all writing different SQL statements, and all writing into the same file for forwarding to the SQL server by radsqlrelay.

Which doesn't work with POSIX locks, as you pointed out. It might work accidentally, but different threads writing to the same file will cause problems. One thread closing a file descriptor will cause another thread to magically lose its lock.

See this is why I wasn't quite sure why you did this on a per module basis. My suggestion would be to use a global hash of filenames -> FDs, which is shared between all things that write to log files on the server. That's sort of the point of a separate FD API, to add a layer on top of the broken POSIX locking to reflect lock states back into things within the same process space. My other suggestion to use multiple FDs would also work alleviate some of the contention. Assuming hash table is already initialised. typedef struct fr_fd_t { fr_pool_t parent; int fd; struct fr_fd_t next; } fr_fd_t; typedef struct fr_pool_t { int in_use; //!< How many file descriptors are in use int in_pool; //!< How many file descriptors are open for this file mutex mutex; //!< Protect access to the pool. fr_fd_t fd; //!< Head of FD list } fr_pool_t; get_fd(filename, bytes_to_lock) { lock(hash) pool = find(filename) if (!pool) { /* new pool */ } lock(pool) unlock(hash) pool->in_use++ /* We don't want this to be removed whilst were using it */ for (fd = pool->fd; fd->next && fd->in_use; fd = fd->next); if (fd->in_use) fd = new_fd() /* add a new fd to the pool for this file (maybe limit this to n FDs) */ lseek(fd, pool->offset, SEEK_CUR) fcntl() /* add range lock */ fd->in_use = true pool->offset += bytes_to_lock /* Set new offset */ unlock(pool) return fd } release_fd(fd) { pool = fd->parent lock(pool) fctnl() /* release range lock */ fd->in_use = false; pool->in_use-- } You can just use one mutex, but two would probably be better. You really want to limit the critical region for the one global mutex, and locking another mutex is probably quicker than doing a bunch of system calls. There's also an issue one what you do if there are no more FDs available. You probably don't want to drop the message... Maybe the max number of FDs should equal the max number of threads + 1. You can't close them whilst something is using any of the FDs in the pool. So this has to be managed carefully. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2