Zeno did remark that we should restart when more than 100 sessions are active. Done with commit Exit if more than 100 sessions are active
It looks like running cleanup_active_agents_in_compositions in bin/admin did not finish correctly. http://ch.oddb.org/de/gcc/search/zone/drugs/search_query/00279/search_type/st_registration?#best_result shows correctly the inactive_atents (Hilfsstoffe), but not http://ch.oddb.org/de/gcc/show/reg/43225/seq/02/pack/001. Called cleanup_active_agents_in_compositions via bin/admin on thinpowen again at 2015-08-31 09:08:01 +0200. Waiting for job to complete. Method completed at 2015-08-31 09:15:37 +0200. Restarted ch.oddbd. And now the inactive agents do not show up again. Why? We have a missing comp.odba_store after calling the (non-modifying version of comp.cleanup_old_active_agent).
After adding this and rerunning the command I did see
leanup_old_active_agent 2015-08-31 09:41:00 +0200: nil 17719/54 before [1, "nil"] after 1/0 failsafe rescued DBI::ProgrammingError < StandardError /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:62:in `rescue in execute': /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:37:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/statement.rb:116:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:263:in `block in ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:553:in `store_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:512:in `store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:274:in `odba_isolated_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:395:in `block in odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:380:in `odba_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2219:in `block (2 levels) in cleanup_active_agents_in_compositions' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2212:in `block in cleanup_active_agents_in_compositions' /var/www/oddb.org/src/util/oddbapp.rb:2210:in `each' /var/www/oddb.org/src/util/oddbapp.rb:2210:in `cleanup_active_agents_in_compositions' (eval):1:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/failsafe.rb:10:in `call' /var/www/oddb.org/src/util/failsafe.rb:10:in `failsafe' /var/www/oddb.org/src/util/oddbapp.rb:1664:in `block in _admin'
After restarting again it stopped working after cleanup_old_active_agent 2015-08-31 09:42:42 +0200: nil 24785/04 before [1, "nil"] after 1/0
Stopping apache2, reloading thinpowers db-dump of yesterday and running cleanup_active_agents_in_compositions with apache2 disabled. This time it stopped after cleanup_old_active_agent 2015-08-31 10:15:35 +0200: nil 38210/02 before [1, "nil"] after 1/0
. bin/admin shows a "Connection closed". And new commands are always refused with -> druby://localhost:10000 - #<Errno::ECONNREFUSED: Connection refused - connect(2)>
. And the "Oddb (OddbApp) process cannot be killed normally. Only with a kill -9.
After the kill -9 and restarting all services I got the following error
cleanup_old_active_agent 2015-08-31 10:28:26 +0200: nil 38210/02 before [1, 0] after 1/0 ODBA::Stub was unable to replace Array#34182533 from ODDB::Composition:#9436670 failsafe rescued NoMethodError < StandardError undefined method `size' for nil:NilClass /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:2216:in `block (2 levels) in cleanup_active_agents_in_compositions' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2212:in `block in cleanup_active_agents_in_compositions' /var/www/oddb.org/src/util/oddbapp.rb:2210:in `each' /var/www/oddb.org/src/util/oddbapp.rb:2210:in `cleanup_active_agents_in_compositions' (eval):1:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/failsafe.rb:10:in `call' /var/www/oddb.org/src/util/failsafe.rb:10:in `failsafe' /var/www/oddb.org/src/util/oddbapp.rb:1664:in `block in _admin'
Reworking cleanup_active_agents_in_compositions to catch the DBI/NoMethodErrors and continuing in this case. Now I get
10/02 before [1, 0] after 1/0 failsafe rescued NoMethodError < StandardError undefined method `size' for Aspirin.Preisvergleich.csv:ODDB::InvoiceItem /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:2223:in `block (2 levels) in cleanup_active_agents_in_compositions' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2219:in `block in cleanup_active_agents_in_compositions' /var/www/oddb.org/src/util/oddbapp.rb:2217:in `each' /var/www/oddb.org/src/util/oddbapp.rb:2217:in `cleanup_active_agents_in_compositions' (eval):1:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:1665:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/failsafe.rb:10:in `call' /var/www/oddb.org/src/util/failsafe.rb:10:in `failsafe' /var/www/oddb.org/src/util/oddbapp.rb:1664:in `block in _admin'
Added some debug output to find the failing item which showed cleanup_old_active_agent 2015-08-31 11:25:47 +0200: 38211/01
. Okay. Here we have weird error in the database, bin/admin reports
registration('38211').sequence('01').compositions.first.inactive_agents.oid -> 34182533 ch.oddb> registration('38211').active? -> false
After fixing this error I got another one
cleanup_old_active_agent 2015-08-31 12:16:32 +0200: 43522/03 Array NilClass active? true failsafe rescued PG::UnableToSend < StandardError /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/exec.rb:11:in `exec': /var/www/oddb.org/src/util/oddbapp.rb:1667:in `instance_eval' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/exec.rb:11:in `exec' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/database.rb:310:in `_exec' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/tuples.rb:36:in `block in column_info' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/tuples.rb:25:in `upto' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/tuples.rb:25:in `column_info' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:83:in `column_info' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/statement.rb:158:in `column_names' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/statement.rb:122:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:263:in `block in ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:553:in `store_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:512:in `store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:274:in `odba_isolated_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:395:in `block in odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:380:in `odba_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2234:in `block (2 levels) in cleanup_active_agents_in_compositions' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2221:in `block in cleanup_active_agents_in_compositions' /var/www/oddb.org/src/util/oddbapp.rb:2219:in `each' /var/www/oddb.org/src/util/oddbapp.rb:2219:in `cleanup_active_agents_in_compositions' (eval):1:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/oddbapp.rb:1667:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:1667:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/failsafe.rb:10:in `call' /var/www/oddb.org/src/util/failsafe.rb:10:in `failsafe' /var/www/oddb.org/src/util/oddbapp.rb:1666:in `block in _admin'
The I got another error
cleanup_active_agents_in_compositions 2015-08-31 12:43:00 +0200: 48725/04 Array NilClass active? true cleanup_active_agents_in_compositions: rescue lost synchronization with server: got message type "", length 1124073472 socket not open cleanup_active_agents_in_compositions 2015-08-31 12:43:00 +0200: skipped 48725/04/usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:62:in `rescue in execute': socket not open (DBI::ProgrammingError) from /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:37:in `execute' from /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/base_classes/database.rb:96:in `execute' from /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/database.rb:81:in `execute' from /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/database.rb:128:in `select_all' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:39:in `block in method_missing' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:29:in `next_connection' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:38:in `method_missing' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:508:in `restore_collection' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:236:in `fetch_collection' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:632:in `restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:318:in `block in fetch_or_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `call' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `fetch_or_do' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:317:in `fetch_or_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:65:in `block in bulk_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:62:in `each' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:62:in `bulk_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:56:in `bulk_fetch' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:260:in `fetch_collection' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:632:in `restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:318:in `block in fetch_or_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `call' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `fetch_or_do' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:317:in `fetch_or_restore' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:640:in `restore_object' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:605:in `load_object' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:226:in `block in fetch' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `call' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `fetch_or_do' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:225:in `fetch' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:49:in `odba_receiver' from /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' from /var/www/oddb.org/src/util/oddbapp.rb:230:in `clean_invoices' from /var/www/oddb.org/src/util/oddbapp.rb:1556:in `clean' from /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:140:in `block (3 levels) in run_cleaner' from <internal:prelude>:10:in `synchronize' from /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:139:in `block (2 levels) in run_cleaner' from /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:137:in `loop' from /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:137:in `block in run_cleaner'
I think I must limit the number of calls/threads to postges. Did not work, but after adding some sleeps I just must wait for the update to finish. This seems to work. Dropping and reimporting thinpowers' database and running cleanup_active_agents_in_compositions again. With a sleep time of only 1 (instaed of 5) the call terminated after emitting cleanup_active_agents_in_compositions 2015-08-31 14:03:31 +0200: Skip inactive 42118/02 Array NilClass active? false
Using bin/admin shows that after restarting oddbd the last cleanup did work fine
ch.oddb> registration('42045').sequence('04').compositions.first.inactive_agents.size -> 6 ch.oddb> registration('42045').sequence('04').compositions.first.active_agents.size -> 7 ch.oddb> registration('42124').sequence('01').compositions.first.inactive_agents.size -> undefined method `size' for nil:NilClass
Dropping and reloading thinpowers' database and trying with sleep(5) again. Cleanup works fine till 29971, but stopps as soon as I start a watir smoktest.
Trying to debug the problem.
ps -ef | grep ruby root 14926 23140 0 14:46 pts/1 00:00:00 sudo -u apache /usr/local/bin/ruby bin/oddbd sudo strace -f -p 14926 Process 14926 attached select(7, [3 6], [], NULL, NULL sudo lsof -p 14926 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME sudo 14926 root cwd DIR 8,5 4096 1708629 /var/www/oddb.org sudo 14926 root rtd DIR 8,5 4096 2 / sudo 14926 root txt REG 8,5 134160 1054973 /usr/bin/sudo sudo 14926 root mem REG 8,5 5832 1048843 /lib64/security/pam_deny.so sudo 14926 root mem REG 8,5 18544 1048852 /lib64/security/pam_limits.so sudo 14926 root mem REG 8,5 5920 1048862 /lib64/security/pam_permit.so sudo 14926 root mem REG 8,5 34968 3419457 /lib64/libcrypt-2.18.so sudo 14926 root mem REG 8,5 47568 1048875 /lib64/security/pam_unix.so sudo 14926 root mem REG 8,5 14264 1048842 /lib64/security/pam_env.so sudo 14926 root mem REG 8,5 88472 934108 /lib64/libz.so.1.2.8 sudo 14926 root mem REG 8,5 55712 1048881 /lib64/libpam.so.0.83.1 sudo 14926 root mem REG 8,5 288608 1055025 /usr/lib64/sudo/sudoers.so sudo 14926 root mem REG 8,5 51520 3419475 /lib64/libnss_files-2.18.so sudo 14926 root mem REG 8,5 43384 3419479 /lib64/libnss_nis-2.18.so sudo 14926 root mem REG 8,5 88888 3419478 /lib64/libnsl-2.18.so sudo 14926 root mem REG 8,5 35528 3419481 /lib64/libnss_compat-2.18.so sudo 14926 root mem REG 8,5 1728728 3419484 /lib64/libc-2.18.so sudo 14926 root mem REG 8,5 14600 3419458 /lib64/libdl-2.18.so sudo 14926 root mem REG 8,5 10464 3419482 /lib64/libutil-2.18.so sudo 14926 root mem REG 8,5 136488 3419483 /lib64/ld-2.18.so sudo 14926 root mem REG 8,5 1867680 6291496 /usr/lib64/locale/locale-archive sudo 14926 root mem REG 8,5 26244 6291495 /usr/lib64/gconv/gconv-modules.cache sudo 14926 root mem REG 8,5 38615 924331 /usr/share/locale/de/LC_MESSAGES/sudoers.mo sudo 14926 root 0u CHR 136,1 0t0 4 /dev/pts/1 sudo 14926 root 1w FIFO 0,8 0t0 43906 pipe sudo 14926 root 2w FIFO 0,8 0t0 43906 pipe sudo 14926 root 3u unix 0xffff8804035fa400 0t0 34623 socket sudo 14926 root 5u unix 0xffff8804009572c0 0t0 34625 socket sudo 14926 root 6r FIFO 0,8 0t0 34621 pipe sudo 14926 root 7w FIFO 0,8 0t0 34621 pipe
Doing the work in a separate thread seems to work a little better, as after starting the smoketest the work continues for about 7 minutes. Maybe I must add an additional mutex as in src/model/fachinfo.rb. This hangs, too. Adding a timeout and trying to continue with next element.
Still getting problems. In a separate bin/admin Thread.list.each {|t| $stdout.puts t.backtrace}
showed the stack trace of all threads. The most interesting seems to be
/var/www/oddb.org/src/util/oddbapp.rb:1668:in `instance_eval' /var/www/oddb.org/src/util/oddbapp.rb:1668:in `block (2 levels) in _admin' /var/www/oddb.org/src/util/failsafe.rb:10:in `call' /var/www/oddb.org/src/util/failsafe.rb:10:in `failsafe' /var/www/oddb.org/src/util/oddbapp.rb:1667:in `block in _admin' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/exec.rb:15:in `exec_prepared' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/database.rb:314:in `_exec_prepared' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:55:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/statement.rb:116:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:263:in `block in ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:553:in `store_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:512:in `store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:274:in `odba_isolated_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:395:in `block in odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:380:in `odba_store' /var/www/oddb.org/src/util/oddbapp.rb:2231:in `cleanup_one_composition' /var/www/oddb.org/src/util/oddbapp.rb:2274:in `block (5 levels) in cleanup_active_agents_in_compositions' /usr/local/lib/ruby/1.9.1/timeout.rb:68:in `timeout'but I found a second thread (run_in_cleaner) with
bin/oddbd:51:in `<main>' /var/www/oddb.org/src/util/today.rb:13:in `block (2 levels) in <class:Object>' /var/www/oddb.org/src/util/today.rb:8:in `loop' /var/www/oddb.org/src/util/today.rb:8:in `block in <class:Object>' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:488:in `block (2 levels) in start_cleaner' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:487:in `loop' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:487:in `block in start_cleaner' /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:138:in `block (2 levels) in run_cleaner' /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:137:in `loop' /usr/local/lib/ruby/gems/1.9.1/gems/sbsm-1.2.3/lib/sbsm/drbserver.rb:137:in `block in run_cleaner' /var/www/oddb.org/src/util/oddbapp.rb:2152:in `block (2 levels) in log_size' /var/www/oddb.org/src/util/oddbapp.rb:2103:in `loop' /var/www/oddb.org/src/util/oddbapp.rb:2103:in `block in log_size' /usr/local/lib/ruby/1.9.1/drb/drb.rb:941:in `accept' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1574:in `main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1424:in `block in run' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1548:in `perform_without_block' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1508:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:566:in `load' /usr/local/lib/ruby/1.9.1/drb/drb.rb:612:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop' /usr/local/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/exec.rb:19:in `prepare' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/database.rb:318:in `_prepare' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:135:in `internal_prepare' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:47:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/base_classes/database.rb:96:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/database.rb:81:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/database.rb:128:in `select_all' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:39:in `block in method_missing' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:29:in `next_connection' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/connection_pool.rb:38:in `method_missing' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:508:in `restore_collection' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:236:in `fetch_collection' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:632:in `restore' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:318:in `block in fetch_or_restore' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `call' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `fetch_or_do' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:317:in `fetch_or_restore' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:640:in `restore_object' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:605:in `load_object' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:226:in `block in fetch' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `call' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:313:in `fetch_or_do' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:225:in `fetch' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:49:in `odba_receiver' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/stub.rb:112:in `method_missing' /var/www/oddb.org/src/util/oddbapp.rb:2257:in `block in cleanup_active_agents_in_compositions' /var/www/oddb.org/src/util/oddbapp.rb:2255:in `each' /var/www/oddb.org/src/util/oddbapp.rb:2255:in `cleanup_active_agents_in_compositions'
Protecting cleanup_one_composition and log_size with @mutex. Adding some debug output and trying to see, whether this okay.
Banging my head, why the command still fails. Killed thread log_size before starting cleanup_active_agents_in_compositions. This did not help neither.
Problem seems still to be inside odba_store.
/usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/exec.rb:15:in `exec_prepared' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/database.rb:314:in `_exec_prepared' /usr/local/lib/ruby/gems/1.9.1/gems/dbd-pg-0.3.9/lib/dbd/pg/statement.rb:55:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/dbi-0.4.5/lib/dbi/handles/statement.rb:116:in `execute' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:263:in `block in ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/storage.rb:262:in `ensure_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:553:in `store_object_connections' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/cache.rb:512:in `store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:274:in `odba_isolated_store' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:395:in `block in odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `each' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:392:in `odba_store_unsaved' /usr/local/lib/ruby/gems/1.9.1/gems/odba-1.1.0/lib/odba/persistable.rb:380:in `odba_store' /var/www/oddb.org/src/util/oddbapp.rb:2233:in `cleanup_one_composition' /var/www/oddb.org/src/util/oddbapp.rb:2281:in `block (5 levels) in cleanup_active_agents_in_compositions'
What did I achieve today? Running cleanup_active_agents_in_compositions does no more block access via oddbd/apache2. Results survive correctly a restart of oddbd. For me it looks as if the error stems either from a wrecked database or an err in odba/or dbd-pg gem. Tomorrow will add a parameter to cleanup_active_agents_in_compositions to be able to restart from a given IKSNR and finish the update of the database in smaller steps.