Back Midas Rome Roody Rootana
  Midas DAQ System, Page 101 of 150  Not logged in ELOG logo
New entries since:Wed Dec 31 16:00:00 1969
ID Date Author Topicdown Subject
  655   08 Oct 2009 Exaos LeeBug ReportMultiple definition of `SqlODBC::SqlODBC()
I found there are two SqlODBC defined in different sources.
$ grep -n "class SqlODBC" src/*
src/history_odbc.cxx:282:class SqlODBC: public SqlBase
src/history_sql.cxx:293:class SqlODBC: public SqlBase
Both of them will be archived into one library libmidas.a if "HAVE_ODBC" defined. Then if you build a shared library, you will
get a link error as the following:
Linking CXX shared library lib/libmidas.so
/usr/bin/cmake -E cmake_link_script CMakeFiles/midas-shared.dir/link.txt --verbose=1
/usr/bin/c++  -fPIC   -shared -Wl,-soname,libmidas.so -o lib/libmidas.so CMakeFiles/midas-shared.dir/src/ftplib.c.o CMakeFiles/midas-shared.dir/src/midas.c.o CMakeFiles/midas-shared.dir/src/system.c.o CMakeFiles/midas-shared.dir/src/mrpc.c.o CMakeFiles/midas-shared.dir/src/odb.c.o CMakeFiles/midas-shared.dir/src/ybos.c.o CMakeFiles/midas-shared.dir/src/history.c.o CMakeFiles/midas-shared.dir/src/alarm.c.o CMakeFiles/midas-shared.dir/src/elog.c.o CMakeFiles/midas-shared.dir/opt/DAQ/repos/bot/mxml/mxml.c.o CMakeFiles/midas-shared.dir/opt/DAQ/repos/bot/mxml/strlcpy.c.o CMakeFiles/midas-shared.dir/src/history_odbc.cxx.o CMakeFiles/midas-shared.dir/src/history_sql.cxx.o 
CMakeFiles/midas-shared.dir/src/history_sql.cxx.o: In function `SqlODBC':
/opt/DAQ/repos/bot/midas/src/history_sql.cxx:200: multiple definition of `SqlODBC::SqlODBC()'
CMakeFiles/midas-shared.dir/src/history_odbc.cxx.o:/opt/DAQ/repos/bot/midas/src/history_odbc.cxx:315: first defined here
...
history_odbc.cxx:727: first defined here
collect2: ld returned 1 exit status
make[2]: *** [lib/libmidas.so] Error 1

Why is the class "SqlODBC" duplicated?
  656   09 Oct 2009 Konstantin OlchanskiBug Reportchange to building and linking libmidas.so, mserver linking fails when using shared library
> --- Makefile
> < 	ld -shared -o $@ $^ $(LIBS) -lc
> ---
> > 	$(CXX) -shared -o $@ $^ $(LIBS) -lc

Will do. We also have a long standing request to change shared library name from lidmidas.so to libmidas-shared.so.

Different name for the .so file will permit us to build the shared library by default, but still link all MIDAS executables
with the static libmidas.a.

(there is no benefit from linking MIDAS executables - mlogger, mhttpd, etc - with the shared library,
and there is a significant cost in confusion from version skew between the executables and shared
libraries - I have had enough midnight calls "why did odbedit stop working? Oh, who changed LD_LIBRARY_PATH
and why is it now binding against this obsolete libmidas.so left over from 2 years ago?").

For user applications you can do whatever, but for MIDAS core applications I strongly suggest that they
be linked to the midas static library.

K.O.
  657   09 Oct 2009 Konstantin OlchanskiBug ReportMultiple definition of `SqlODBC::SqlODBC()
> Linking CXX shared library lib/libmidas.so
/usr/bin/c++  ... -o lib/libmidas.so ... CMakeFiles/midas-shared.dir/src/history_odbc.cxx.o 
CMakeFiles/midas-shared.dir/src/history_sql.cxx.o 
CMakeFiles/midas-shared.dir/src/history_sql.cxx.o: In function `SqlODBC':
/opt/DAQ/repos/bot/midas/src/history_sql.cxx:200: multiple definition of `SqlODBC::SqlODBC()'
CMakeFiles/midas-
shared.dir/src/history_odbc.cxx.o:/opt/DAQ/repos/bot/midas/src/history_odbc.cxx:315: first defined 
here
> Why is the class "SqlODBC" duplicated?

This is interesting. I do not think my C++ book spells it out that I cannot have class A in foo.cxx
and a class A in bar.cxx. In fact I already discovered that the two classes A will collide (duplicate default 
constructor A::A, even if all other member functions are different) if I link an executable that uses both 
foo.o and bar.o.

Is there a way around this problem? In C, I can declare functions and variables "static" to "hide" them
from the linker.

What is the C++ equivalent for classes? (Any C++ experts here?)

In this specific case, the file history_odbc.cxx will disappear with the next commit of mhttpd, hopefully 
today. mlogger and mh2sql already do not use it.

And I will commit the Makefile change renaming libmidas.so to libmidas-shared.so, so we can build it 
by default but still link midas core executables to the normal midas library.

This will catch such a problem if it happens again.

K.O.
  658   09 Oct 2009 Exaos LeeBug ReportBuilding error of history_midas.cxx due to missing declaration
Platform: Debian Linux testing
Compiler: gcc 4.3.4 (Debian 4.3.4-2)
Arch: x86
Description:
  The "g++" is whining while compiling history_midas.cxx. Please see the attached log file.
This can be fixed by add "#include <cstdlib>" to the C++ source. You know, different versions
of g++ don't act the same way. I think, maybe in version 4.2 or before, g++ can automatically
include the C header "stdlib.h" (which in C++ should be <cstdlib> because of some confusion
between C and C++), but not in version 4.3 or later. I tested g++-4.4, the problem still exists.
And g++-4.2 gives no error.
Attachment 1: build-20091010.log
g++ -c -g -O2 -Wall -Wuninitialized -Iinclude -Idrivers -I../mxml -Llinux/lib -DINCLUDE_FTPLIB   -D_LARGEFILE64_SOURCE -DHAVE_MYSQL -I/usr/include/mysql -DHAVE_ODBC -DHAVE_ZLIB -DOS_LINUX -fPIC -Wno-unused-function -o linux/lib/history_midas.o src/history_midas.cxx
src/history_midas.cxx: In function 'WORD get_variable_id(DWORD, const char*, const char*)':
src/history_midas.cxx:45: error: 'atoi' was not declared in this scope
src/history_midas.cxx:47: warning: comparison between signed and unsigned integer expressions
src/history_midas.cxx:55: error: 'strchr' was not declared in this scope
src/history_midas.cxx:75: error: 'free' was not declared in this scope
src/history_midas.cxx:81: error: 'free' was not declared in this scope
src/history_midas.cxx: In function 'WORD get_variable_id_tags(const char*, const char*)':
src/history_midas.cxx:119: error: 'atoi' was not declared in this scope
src/history_midas.cxx:121: warning: comparison between signed and unsigned integer expressions
src/history_midas.cxx:127: error: 'strchr' was not declared in this scope
src/history_midas.cxx: In function 'void list_add(poor_mans_list*, const char*)':
src/history_midas.cxx:182: error: 'strlen' was not declared in this scope
src/history_midas.cxx:188: error: 'realloc' was not declared in this scope
src/history_midas.cxx:193: error: 'memcpy' was not declared in this scope
src/history_midas.cxx: In member function 'virtual int MidasHistory::hs_connect(const char*)':
src/history_midas.cxx:284: error: 'memset' was not declared in this scope
src/history_midas.cxx: In member function 'int MidasHistory::GetEventsFromOdbEvents(std::vector<std::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*)':
src/history_midas.cxx:471: error: 'strchr' was not declared in this scope
src/history_midas.cxx: In member function 'int MidasHistory::GetEventsFromOdbTags(std::vector<std::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*)':
src/history_midas.cxx:531: error: 'strtoul' was not declared in this scope
src/history_midas.cxx: In member function 'int MidasHistory::GetTagsFromHS(const char*, std::vector<TAG, std::allocator<TAG> >*)':
src/history_midas.cxx:778: error: 'free' was not declared in this scope
src/history_midas.cxx: In member function 'int MidasHistory::GetTagsFromOdb(const char*, std::vector<TAG, std::allocator<TAG> >*)':
src/history_midas.cxx:820: error: 'atoi' was not declared in this scope
src/history_midas.cxx:824: warning: comparison between signed and unsigned integer expressions
src/history_midas.cxx:874: error: 'strchr' was not declared in this scope
src/history_midas.cxx:903: error: 'strchr' was not declared in this scope
src/history_midas.cxx: In member function 'virtual int MidasHistory::hs_read(time_t, time_t, time_t, int, const char**, const char**, const int*, int*, time_t**, double**, int*)':
src/history_midas.cxx:975: error: 'malloc' was not declared in this scope
src/history_midas.cxx:994: error: 'memset' was not declared in this scope
src/history_midas.cxx:1006: error: 'realloc' was not declared in this scope
src/history_midas.cxx:1016: error: 'malloc' was not declared in this scope
src/history_midas.cxx:1070: error: 'free' was not declared in this scope
src/history_midas.cxx:1072: error: 'free' was not declared in this scope
make: *** [linux/lib/history_midas.o] Error 1
  659   11 Oct 2009 Konstantin OlchanskiBug ReportBuilding error of history_midas.cxx due to missing declaration
>  The "g++" is whining while compiling history_midas.cxx. Please see the attached log file.

Fixed. svn 4594. K.O.
  660   11 Oct 2009 Konstantin OlchanskiBug Reportchange to building and linking libmidas.so, mserver linking fails when using shared library
> > > 	$(CXX) -shared -o $@ $^ $(LIBS) -lc

Done.
MIDAS shared library renamed from libmidas.so to libmidas-shared.so and always build on Linux (.so) and MacOS (.dylib and .so bundle).

Users who wish to link their applications to the shared library should change their Makefile from "gcc ... -lmidas" to "gcc ... -lmidas-shared".

MIDAS core applications (mhttpd, mlogger, etc) are linked to the static library to permit multiple versions of midas to be used
at the same time (LD_LIBRARY_PATH should point to the shared library for *which* midas?!?), avoid problems with wrong setting
of LD_LIBRARY_PATH and to avoid problems with version skew (which we found unavoidable once a midas daq is used for a year or
more - main reason we gave up on using the midas shared library in the first place).

svn rev 4594
K.O.
  661   11 Oct 2009 Konstantin OlchanskiBug ReportMultiple definition of `SqlODBC::SqlODBC()
> > Why is the class "SqlODBC" duplicated?
> 
> This is interesting. I do not think my C++ book spells it out that I cannot have class A in foo.cxx
> and a class A in bar.cxx.

I guess nobody knows the answer to this C++ puzzle. In any case history_odbc.cxx is not used anymore removing duplication of class SqlODBC.

svn rev 4594
K.O.
  676   25 Nov 2009 Konstantin OlchanskiBug Reportonce in 100 years midas shared memory bug
We were debugging a strange problem in the event builder, where out of 14
fragments, two fragments were always getting serial number mismatches and the
serial numbers were not sequentially increasing (the other 12 fragments were
just fine).

Then we noticed in the event builder debug output that these 2 fragments were
getting assigned the same buffer handle number, despite having different names -
BUF09 and BUFTPC.

Then we looked at "ipcs", counted the buffers, and there are only 13 buffers for
14 frontends.

Aha, we went, maybe we have unlucky buffer names, renamed BUFTPC to BUFAAA and
everything started to work just fine.

It turns out that the MIDAS ss_shm_open() function uses "ftok" to convert buffer
names to SystemV shared memory keys. This "ftok" function promises to create
unique keys, but I guess, just not today.

Using a short test program, I confirmed that indeed we have unlucky buffer names
and ftok() returns duplicate keys, see below.

Apparently ftok() uses the low 16 bits of the file inode number, but in our
case, the files are NFS mounted and inode numbers are faked inside NFS. When I
run my test program on a different computer, I get non-duplicate keys. So I
guess we are double unlucky.

Test program:

#include <stdio.h>
#include <sys/types.h>
#include <sys/ipc.h>

int main(int argc, char* argv[])
{
  //key_t ftok(const char *pathname, int proj_id);
  
  int k1 = ftok("/home/t2kdaq/midas/nd280/backend/.BUF09.SHM", 'M');
  int k2 = ftok("/home/t2kdaq/midas/nd280/backend/.BUFTPC.SHM", 'M');
  int k3 = ftok("/home/t2kdaq/midas/nd280/backend/.BUFFGD.SHM", 'M');

  printf("key1: 0x%08x, key2: 0x%08x, key3: 0x%08x\n", k1, k2, k3);
  return 0;
}

[t2kfgd@t2knd280logger ~/xxx]$ g++ -o ftok -Wall ftok.cxx
[t2kfgd@t2knd280logger ~/xxx]$ ./ftok
key1: 0x4d138154, key2: 0x4d138154, key3: 0x4d138152

Also:

[t2kfgd@t2knd280logger ~/xxx]$ ls -li ...
14385492 -rw-r--r-- 1 t2kdaq t2kdaq  8405052 Nov 24 17:42
/home/t2kdaq/midas/nd280/backend/.BUF09.SHM
36077906 -rw-r--r-- 1 t2kdaq t2kdaq 67125308 Nov 26 10:19
/home/t2kdaq/midas/nd280/backend/.BUFFGD.SHM
36077908 -rw-r--r-- 1 t2kdaq t2kdaq  8405052 Nov 25 15:53
/home/t2kdaq/midas/nd280/backend/.BUFTPC.SHM

(hint: print the inode numbers in hex and compare to shm keys printed by the
program)

K.O.
  678   26 Nov 2009 Konstantin OlchanskiBug Report"mserver -s" is broken
I notice that "mserver -s" (a non-default mode of operation) does not work right
- if I connect odbedit for the first time, all is okey, if I connect the second
time, mserver crashes - because after the first connection closed,
rpc_deregister_functions() was called, rpc_list is deleted and causes a crash
later on. Because everybody uses the default "mserver -m" mode, I am not sure
how important it is to fix this.
K.O.
  680   27 Nov 2009 Stefan RittBug Report"mserver -s" is broken
> I notice that "mserver -s" (a non-default mode of operation) does not work right
> - if I connect odbedit for the first time, all is okey, if I connect the second
> time, mserver crashes - because after the first connection closed,
> rpc_deregister_functions() was called, rpc_list is deleted and causes a crash
> later on. Because everybody uses the default "mserver -m" mode, I am not sure
> how important it is to fix this.
> K.O.

"mserver -s" is there for historical reasons and for debugging. I started originally 
with a single process server back in the 90's, and only afterwards developed the multi 
process scheme. The single process server now only works for one connection and then 
crashes, as you described. But it can be used for debugging any server connection, 
since you don't have to follow the creation of a subprocess with your debugger, and 
therefore it's much easier. But after the first connection has been closed, you have 
to restart that single server process. Maybe one could add some warning about that, or 
even fix it, but it's nowhere used in production mode.
  681   27 Nov 2009 Konstantin OlchanskiBug Report"mserver -s" is broken
> 
> "mserver -s" is there for historical reasons and for debugging.
>

I confirm that my modification also works for "mserver -s". I also added an assert() to the
place in midas.c were it eventually crashes, to make it more obvious for the next guys.

K.O.
  728   06 Oct 2010 Konstantin OlchanskiBug Reportmhttpd "edit on start" breakage
very recent mhttpd mangles spaces in URL encoding-decoding and I cannot create or delete entries in for 
example "/experiment/edit on start". For example attempt to delete "/experiment/Pedestals Run" 
produces:
<h1>Cannot find key Experiment/edit%20on%20start/Pedestals run</h1>
(notice "%20" instead of spaces. further navigation sometimes replaces the "%" sign with "%25" making it 
even more mangled)

this used to work. looks like a call to URL unmangling went missing somewhere.
K.O.
  732   17 Nov 2010 Stefan RittBug Reportmhttpd "edit on start" breakage
> very recent mhttpd mangles spaces in URL encoding-decoding and I cannot create or delete entries in for 
> example "/experiment/edit on start". For example attempt to delete "/experiment/Pedestals Run" 
> produces:
> <h1>Cannot find key Experiment/edit%20on%20start/Pedestals run</h1>
> (notice "%20" instead of spaces. further navigation sometimes replaces the "%" sign with "%25" making it 
> even more mangled)
> 
> this used to work. looks like a call to URL unmangling went missing somewhere.
> K.O.

Thanks for reporting. Fixed in SVN revision 4882. Actually I outcommented the fix some time ago and forgot to 
put it back. Now I hope that this does not blow anything else...

- Stefan
  734   23 Dec 2010 Konstantin OlchanskiBug Reportodb corruption, odb race condition?
The following script makes midas very unhappy and eventually causes odb corruption. I suspect the reason is some kind of race condition collision between client 
creation and destruction code and the watchdog activity (each client periodically runs cm_watchdog() to check if other clients are still alive, O(NxN) total complexity). 
Amongst messages appearing in midas.log:

Thu Dec 23 11:59:08 2010 [ODBEdit28,INFO] Client 'unknown' on buffer 'SYSMSG' removed by bm_open_buffer because client pid 20463 does not exist
Thu Dec 23 11:59:09 2010 [ODBEdit43,INFO] Client 'unknown' on buffer 'SYSMSG' removed by cm_watchdog because client pid 20465 does not exist
Thu Dec 23 12:11:21 2010 [ODBEdit,ERROR] [odb.c:1061:db_open_database,ERROR] Removing client 'ODBEdit11', pid 21536, index 27 because the pid no longer exists
Thu Dec 23 17:06:15 2010 [ODBEdit,ERROR] [odb.c:988:db_open_database,ERROR] maximum number of clients exceeded
Thu Dec 23 12:10:30 2010 [ODBEdit9,ERROR] [odb.c:3247:db_get_value,ERROR] "Name" is of type NULL, not STRING

The last message about <"Name" is of type NULL> appears during normal operation of the ND280 DAQ, leading me into these investigations.

Notes:
a) the script runs at most 50 copies of odbedit, never exceeding midas.h MAX_CLIENTS value 64, so one does not expect to see messages about "maximum number of 
clients exceeded"
b) the script runs 50 copies of odbedit in parallel, increasing the likelihood of whatever race condition is causing this. In the ND280 system, likelihood of failure is 
increased by the large number of running clients (10-20-30 clients), each client running periodic cm_watchdog, to collide with new client creation or destruction.
c) in other experiments, we do not see this (ok, we do have midas meltdowns once in a while) because (1) we tend to have fewer clients (reduced frequency of 
cm_watchdog), (2) we tend to not start and stop midas clients too often (reduced frequency of running client creation and destruction). (NB it seems like ND280 people 
tend to run many scripts containing odbedit commands, so they effectively start and stop midas clients more often than usual).


#!/usr/bin/perl -w
#$cmd = "odbedit -c \'scl -w\' &";
$cmd = "odbedit -c \'ls -l /system/clients\' &";
for (my $i=0; $i<50; $i++)
{
system $cmd;
}
#end
  735   24 Dec 2010 Konstantin OlchanskiBug Reportodb corruption, odb race condition?
> Thu Dec 23 12:10:30 2010 [ODBEdit9,ERROR] [odb.c:3247:db_get_value,ERROR] "Name" is of type NULL, not STRING

This is caused by a race condition between client removal in cm_delete_client_info() and cm_exist().

The race condition in cm_exist() works like this:
- db_enum_key() returns the hkey (pointer to) the next /System/Clients/PID directory
- the client corresponding to PID is removed, our hkey now refers to a deleted entry
- db_get_value() tries to use the now stale hkey pointing to a deleted entry, complains about invalid key TID.

Because the offending db_get_value() is called with the "create if not found" argument set to TRUE, there is potential
for writing into ODB using a stale hkey, maybe leading to ODB corruption. Other than that, this race condition seems
to be benign.

cm_exist() is called from:
everybody->cm_yield()->al_check()->cm_exist()

Further analysis:
- cm_yield() calls al_check() every 10 sec, al_check() calls cm_exist() to check for "program is not running" alarms.
- in al_check() cm_exist() is called once for each entry in /Programs/xxx, even for programs with no alarms. (Maybe I should change this?)
- assuming 10 programs are running (10 clients), every 10 seconds, cm_exist() will be called 10 times and inside, will loop over 10 clients, exposing the enum-get race condition 10*10=100 times every 10 seconds. Usually, 
ODB /Programs/ has many more entries than there are active clients, further increasing the frequency of exposure of this race condition.

K.O.
  736   24 Dec 2010 Konstantin OlchanskiBug Reportodb corruption, odb race condition?
> > Thu Dec 23 12:10:30 2010 [ODBEdit9,ERROR] [odb.c:3247:db_get_value,ERROR] "Name" is of type NULL, not STRING
> This is caused by a race condition between client removal in cm_delete_client_info() and cm_exist().
> ... this race condition seems to be benign.

Not so benign - after fixing cm_exist() to check the return value of db_get_value() and calling it without the "create" flag,
a crasher turned up inside db_find_key() called by db_get_value() with these stale hkeys. For invalid keys (not TID_KEY),
it would call db_get_path() and crash.

So after adding a check for valid key types, my test script runs much better - all the major weirdness is gone, I only see
rare messages from db_find_key(), db_get_key() and db_get_value() about invalid key and data types (after all,
I did not fix the underlying race condition).

The only remaining problem when running my script is some kind of deadlock between the ODB and SYSMSG semaphores...

K.O.
  737   26 Dec 2010 Konstantin OlchanskiBug Reportrace condition and deadlock between ODB lock and SYSMSG lock in cm_msg()
> 
> The only remaining problem when running my script is some kind of deadlock between the ODB and SYSMSG semaphores...
> 


In theory, we understand how programs that use 2 semaphores to protect 2 shared resources can deadlock
if there are mistakes in how locks are used.

For example, consider 2 semaphores A and B and 2 concurrent
subroutines foo() and bar() running at exactly the same time:

foo() { lock(A); lock(B); do stuff; unlock(B); unlock(A); } and
bar() { lock(B); lock(A); do stuff; unlock(A); unlock(B); }

This system will deadlock immediately with foo() taking semaphore A, bar() taking semaphore B,
then foo() waiting for B and bar() waiting for A forever.

This situation can also be described as a race condition where foo() and bar() are racing each
other to get the semaphores, with the result depending on who gets there first
and, in this case, sometimes the result is deadlock.

In this example, the size of the race condition time window is the wall clock time
between actually locking both semaphores in the sequence "lock(X); lock(Y);". While
locking a semaphore is "instantaneous", the actual function lock() takes time to call
and execute, and this time is not fixed - it can change if the CPU takes a hardware
interrupt (quick), a page fault (when we may have to wait until data is read from the swap file)
or a scheduler interrupt (when we are outright stopped for milliseconds while the CPU runs
some other process).

In reality, subroutines foo() and bar() do not run at exactly the same time, so the probability
of deadlock will depend on how often foo() and bar() are executed, the size of the race condition time window,
the number of processes executing foo() and bar(), and the amount of background activity
like swapping, hardware interrupts, etc.

(Also note that on a single-cpu system, we will probably never see a deadlock between foo() and bar()
because they will never be running at the same time. But the deadlock is still there, waiting
for the lucky moment when the scheduler switches from foo() to bar() just at the wrong place).

There is more on deadlocks and stuff written at:
http://en.wikipedia.org/wiki/Deadlock
http://en.wikipedia.org/wiki/Race_condition

In case of MIDAS, the 2 semaphores are the ODB lock and the SYSMSG lock (also remember about locks
for the shared memory event buffers, SYSTEM, etc, but they seem to be unlikely to deadlock).

The function foo() is any ODB function (db_xxx) that locks ODB and then calls cm_msg() (which locks SYSMSG).

The function bar() is cm_msg() which locks SYSMSG and then calls some ODB db_xxx() function which tries to lock ODB.

(This is made more interesting by cm_watchdog() periodically called by alarm(), where we alternately
take SYSMSG (via bm_cleanup) and ODB locks.)

I think this establishes a theoretical possibility for MIDAS to deadlock on the ODB and SYSMSG semaphores.

In practice, I think we almost never see this deadlock because cm_msg() is not called very often, and during normal
operation, is almost never called from inside ODB functions holding the ODB lock - almost all calls to cm_msg from
ODB functions are made to report some kind of problem with the ODB internal structure, something that "never"
happens.

By "luck" I stumbled into this deadlock when doing the "odbedit" fork-bomb torture tests, when high ODB lock
activity is combined with high cm_msg() activity reporting clients starting and stopping, combined with a large
number of MIDAS clients running, starting and stopping.

So a deadlock I see within 1 minute of running the torture test, other lucky people will see after running an experiment
for 1 year, or 1 month, or 1 day, depending.

In theory, this deadlock can be removed by establishing a fixed order of taking locks. There will never be a deadlock
if we always take the SYSMSG lock first, then ask for the ODB lock.

In practice, it means that using cm_msg() while holding an ODB lock is automatically dangerous
and should be avoided if not forbidden.

And it does work. By refactoring a few places in client startup, shutdown and cleanup code, I made the deadlock "go away",
and my test script (posted in my first message) no longer deadlocks, even if I run hundreds of odbedit's at the same time.

Unfortunately,  it is impractical to audit and refactor all of MIDAS to completely remove this problem. MIDAS call graphs
are sufficiently complicated for making manual analysis of lock sequences infeasible and
I expect any automatic lock analysis tool will be defeated by the cm_watchdog() periodic interrupt.

An improvement is possible if we make cm_msg() safe for calling from inside the ODB db_xxx() function. Instead
of immediately sending messages to SYSMSG (requiring a SYSMSG lock), if ODB is locked, cm_msg() could
save the messages in a buffer, which would be flushed when the ODB lock is released. (This does not fix
all the other places that take ODB and SYSMSG locks in arbitrary order, but I think those places are not as
likely to deadlock, compared to cm_msg()).

However, now that I have greatly reduced the probability of deadlock in the client startup/shutdown/cleanup code,
maybe there is no urgency for changing cm_msg() - remember that if we do not call cm_msg() we will never deadlock -
and during normal operation, cm_msg() is almost never called.

Investigation completed, I will now cleanup, retest and commit my changes to midas.c and odb.c. Looking into this
and writing it up was a good intellectual exercise.

P.S. Also remember that there are locks for shared memory event buffers (SYSTEM, etc), but those do not involve
lock inversion leading to deadlock. I think all lock sequences are like this: SYSTEM->ODB, SYSTEM->SYSMSG->ODB,
there are no inverted sequences SYSMSG->SYSTEM or ODB->SYSTEM and the only deadlocking
sequence SYSTEM->ODB->SYSMSG, does not really involve the SYSTEM lock.

K.O.
  738   29 Dec 2010 Konstantin OlchanskiBug Reportuse of nested locks in MIDAS
A "nested" or "recursive" lock is a special type of lock that permits a lock holder to lock the same resources again and again, without deadlocking on itself. They are 
very useful, but tricky to implement because most system lock primitives (SYSV semaphores, POSIX mutexes, etc) do not permit nested locks, so all the logic for 
"yes, I am the holder of the lock, yes, I can go ahead without taking it again" (plus the reverse on unlocking) has to be done "by hand". As ever, if implemented 
wrong or used wrong, Bad Things happen. Many people dislike nested locks because of the added complexity, but realistically, it is impossible to build a system 
that does not require nested locking at least somewhere.

MIDAS lock primitives - ss_semaphore_wait_for(), db_lock_database() and bm_lock_buffer() implement a type of nested locks.

ODB locks implemented in db_lock_database() fully support nested (recursive) locking and this feature is heavily used by the ODB library. Many ODB db_xxx() 
functions take the ODB lock, do something, then call another ODB function that also takes the ODB lock recursively. This works well.

Unfortunately, the ODB nested lock implementation is NOT thread-safe. (Unless one is connected through the mserver, in which case, db_xxx() functions ARE 
thread-safe because all ODB access is serialized by the mserver RPC mutex).

Event buffer locks implemented in bm_lock_buffer() rely on ss_semaphore_xxx() to provide nested locking.

ss_semaphore_wait_for() uses SYSV semaphores, which do not provide nested locking, except when called from cm_watchdog(). (keep reading).

Because bm_lock_buffer() does not implement nested locking, use of cm_msg() in buffer management code will lead to self-deadlock, as shown in the following 
stack trace, where bm_cleanup() is working on the SYSMSG buffer, locked it, then called cm_msg() which is now waiting on the SYSMSG lock, which we are holding 
ourselves.

(gdb) where
#0  0x00007fff87274e9e in semop ()
#1  0x0000000100024075 in ss_semaphore_wait_for (semaphore_handle=1179654, timeout=300000) at src/system.c:2280
#2  0x0000000100015292 in bm_lock_buffer (buffer_handle=<value temporarily unavailable, due to optimizations>) at src/midas.c:5386
#3  0x000000010000df97 in bm_send_event (buffer_handle=1, source=0x7fff5fbfd430, buf_size=<value temporarily unavailable, due to optimizations>, 
async_flag=0) at src/midas.c:6484
#4  0x000000010000e6f5 in cm_msg (message_type=2, filename=<value temporarily unavailable, due to optimizations>, line=4226, routine=0x10004559f 
"bm_cleanup", format=0x100045550 "Client '%s' on buffer '%s' removed by %s because process pid %d does not exist") at src/midas.c:722
#5  0x000000010001553c in bm_cleanup_buffer_locked (i=<value temporarily unavailable, due to optimizations>, who=0x100045f42 "bm_open_buffer", 
actual_time=869425784) at src/midas.c:4226
#6  0x00000001000167ee in bm_cleanup (who=0x100045f42 "bm_open_buffer", actual_time=869425784, wrong_interval=0) at src/midas.c:4286
#7  0x000000010001ae27 in bm_open_buffer (buffer_name=<value temporarily unavailable, due to optimizations>, buffer_size=100000, 
buffer_handle=0x10006e9ac) at src/midas.c:4550
#8  0x000000010001ae90 in cm_msg_register (func=0x100000c60 <process_message>) at src/midas.c:895
#9  0x0000000100009a13 in main (argc=3, argv=0x7fff5fbff3d8) at src/odbedit.c:2790

This example deadlock is not a normal code path - I accidentally exposed this deadlock sequence by adding some extra locking.

But in normal use, cm_msg() is called quite often from cm_watchdog() and as protection against this type of deadlock, MIDAS
ss_semaphore_xxx() has a special case that permits one level of nesting for locks called by code executed from cm_watchdog(). This is a very
clever implementation of partial nested locking.

So again, we are running into problems with cm_msg() - logically it should be at the very bottom of the system hierarchy - everybody calls it from their most 
delicate places, while holding various locks, etc - but instead, cm_msg() call the whole MIDAS system all over again - it calls ODB functions, event buffer functions, 
etc - mostly to open and to write into the SYSMSG buffer.

If you are reading this, I hope you are getting a better idea of the difference between textbook systems and systems that are used in the field to get some work 
done.

K.O.
  739   29 Dec 2010 Konstantin OlchanskiBug Reportfixed. odb corruption, odb race condition?
> 
> The only remaining problem when running my script is some kind of deadlock between the ODB and SYSMSG semaphores...
> 


I committed changes to odb.c and midas.c fixing a number of places that could corrupt ODB and SYSMSG data, and fixing a number of deadlocks. Without these 
changes, on my Mac, MIDAS will reliably corrupt ODB or deadlock while running my odbedit fork-bomb torture test script. These changes still need to be tested on 
Linux (but I do not expect any problems).

Because my changes do not fix the original race condition in client creation/removal/cleanup, you may still occasionally see messages like this:
13:35:14 [ODBEdit24,ERROR] [odb.c:2112:db_find_key,ERROR] hkey 169592 invalid key type 376
13:35:15 [ODBEdit28,ERROR] [odb.c:3268:db_get_value,ERROR] hkey 162072 entry "Name" is of type NULL, not STRING

For now, I am happy that we no longer corrupt ODB (nor deadlock) and I will work with Stefan on a permanent solution for this.

Special thanks go to the T2K/ND280 experiment, specifically, to Tim Nicholls and to the unnamed person who emailed me their script that executes many odbedit 
commands to setup midas history plots.


svn rev 4930
K.O.


P.S. Below is my torture test script, I usually run many of them in a sequence "./test1.perl >& xxx1; ./test1.perl >& xxx2; ... etc".

#!/usr/bin/perl -w
for (my $i=0; $i<50; $i++)
{
#my $cmd = "odbedit -c \'scl -w\' &";
#my $cmd = "odbedit -c \'ls -l /system/clients\' >& xxx$i &";
my $cmd = "odbedit -c \'ls -l /system/clients\' &";
system $cmd;
}
#end

svn rev 4930
K.O.
  740   17 Jan 2011 Andreas SuterBug ReportProblems with midas history SVN 4936
I have the following problems after updating to midas SVN 4936: the history 
system (web-page via mhttpd) seems to stop working. I checked the history files 
themself and they are indeed written, except that the events ID's are not the 
same anymore (I mean the ones defined under /Equipment/XXX/Common/Event ID), 
rather the mlogger seems to choose an ID by itself.
Currently the only way to get things working again was to recompile midas with 
adding -DOLD_HISTORY to the CFLAGS which is troublesome since it is likely to be 
forgotton with the next SVN update. When looking into the SVN I have the 
impression there is something going on concerning the history system, however
I couldn't find any documentation.
What is the best practice for the future, in order not to run into any problems 
but still being able to look at the old history (also from within the web-page 
via mhttpd)?
ELOG V3.1.4-2e1708b5