--- deliantra/server/lib/cf.pm	2010/04/28 21:07:41	1.531
+++ deliantra/server/lib/cf.pm	2011/04/23 04:56:51	1.563
@@ -1,7 +1,7 @@
 #
 # This file is part of Deliantra, the Roguelike Realtime MMORPG.
 # 
-# Copyright (©) 2006,2007,2008,2009,2010 Marc Alexander Lehmann / Robin Redeker / the Deliantra team
+# Copyright (©) 2006,2007,2008,2009,2010,2011 Marc Alexander Lehmann / Robin Redeker / the Deliantra team
 # 
 # Deliantra is free software: you can redistribute it and/or modify it under
 # the terms of the Affero GNU General Public License as published by the
@@ -22,9 +22,7 @@
 
 package cf;
 
-use 5.10.0;
-use utf8;
-use strict qw(vars subs);
+use common::sense;
 
 use Symbol;
 use List::Util;
@@ -80,6 +78,8 @@
 
 sub WF_AUTOCANCEL () { 1 } # automatically cancel this watcher on reload
 
+our @ORIG_INC;
+
 our %COMMAND      = ();
 our %COMMAND_TIME = ();
 
@@ -95,10 +95,12 @@
 our %REFLECT; # set by us
 
 our $CONFDIR     = confdir;
+
 our $DATADIR     = datadir;
 our $LIBDIR      = "$DATADIR/ext";
 our $PODDIR      = "$DATADIR/pod";
 our $MAPDIR      = "$DATADIR/" . mapdir;
+
 our $LOCALDIR    = localdir;
 our $TMPDIR      = "$LOCALDIR/" . tmpdir;
 our $UNIQUEDIR   = "$LOCALDIR/" . uniquedir;
@@ -126,7 +128,7 @@
 our $BDB_TRICKLE_WATCHER;
 our $DB_ENV;
 
-our @EXTRA_MODULES = qw(pod match mapscript);
+our @EXTRA_MODULES = qw(pod match mapscript incloader);
 
 our %CFG;
 
@@ -235,9 +237,14 @@
 =item cf::wait_for_tick, cf::wait_for_tick_begin
 
 These are functions that inhibit the current coroutine one tick. cf::wait_for_tick_begin only
-returns directly I<after> the tick processing (and consequently, can only wake one process
+returns directly I<after> the tick processing (and consequently, can only wake one thread
 per tick), while cf::wait_for_tick wakes up all waiters after tick processing.
 
+=cut
+
+sub wait_for_tick();
+sub wait_for_tick_begin();
+
 =item @cf::INVOKE_RESULTS
 
 This array contains the results of the last C<invoke ()> call. When
@@ -254,6 +261,12 @@
 
 =cut
 
+sub error(@) { LOG llevError, join "", @_ }
+sub warn (@) { LOG llevWarn , join "", @_ }
+sub info (@) { LOG llevInfo , join "", @_ }
+sub debug(@) { LOG llevDebug, join "", @_ }
+sub trace(@) { LOG llevTrace, join "", @_ }
+
 $Coro::State::WARNHOOK = sub {
    my $msg = join "", @_;
 
@@ -262,16 +275,16 @@
 
    $msg =~ s/([\x00-\x08\x0b-\x1f])/sprintf "\\x%02x", ord $1/ge;
 
-   LOG llevError, $msg;
+   LOG llevWarn, $msg;
 };
 
 $Coro::State::DIEHOOK = sub {
    return unless $^S eq 0; # "eq", not "=="
 
-   warn Carp::longmess $_[0];
+   error Carp::longmess $_[0];
 
    if (in_main) {#d#
-      warn "DIEHOOK called in main context, Coro bug?\n";#d#
+      error "DIEHOOK called in main context, Coro bug?\n";#d#
       return;#d#
    }#d#
 
@@ -306,6 +319,11 @@
 
 #############################################################################
 
+sub fork_call(&@);
+sub get_slot($;$$);
+
+#############################################################################
+
 =head2 UTILITY FUNCTIONS
 
 =over 4
@@ -333,6 +351,20 @@
    } || "[unable to dump $_[0]: '$@']";
 }
 
+=item $scalar = load_file $path
+
+Loads the given file from path and returns its contents. Croaks on error
+and can block.
+
+=cut
+
+sub load_file($) {
+   0 <= aio_load $_[0], my $data
+      or Carp::croak "$_[0]: $!";
+
+   $data
+}
+
 =item $ref = cf::decode_json $json
 
 Converts a JSON string into the corresponding perl data structure.
@@ -348,12 +380,43 @@
 sub encode_json($) { $json_coder->encode ($_[0]) }
 sub decode_json($) { $json_coder->decode ($_[0]) }
 
+=item $ref = cf::decode_storable $scalar
+
+Same as Coro::Storable::thaw, so blocks.
+
+=cut
+
+BEGIN { *decode_storable = \&Coro::Storable::thaw }
+
+=item $ref = cf::decode_yaml $scalar
+
+Same as YAML::XS::Load, but doesn't leak, because it forks (and thus blocks).
+
+=cut
+
+sub decode_yaml($) {
+   fork_call { YAML::XS::Load $_[0] } @_
+}
+
+=item $scalar = cf::unlzf $scalar
+
+Same as Compress::LZF::compress, but takes server ticks into account, so
+blocks.
+
+=cut
+
+sub unlzf($) {
+   # we assume 100mb/s minimum decompression speed (noncompressible data on a ~2ghz machine)
+   cf::get_slot +(length $_[0]) / 100_000_000, 0, "unlzf";
+   Compress::LZF::decompress $_[0]
+}
+
 =item cf::post_init { BLOCK }
 
 Execute the given codeblock, I<after> all extensions have been (re-)loaded,
 but I<before> the server starts ticking again.
 
-The cdoeblock will have a single boolean argument to indicate whether this
+The codeblock will have a single boolean argument to indicate whether this
 is a reload or not.
 
 =cut
@@ -362,6 +425,23 @@
    push @POST_INIT, shift;
 }
 
+sub _post_init {
+   trace "running post_init jobs";
+
+   # run them in parallel...
+
+   my @join;
+
+   while () {
+      push @join, map &Coro::async ($_, 0), @POST_INIT;
+      @POST_INIT = ();
+
+      @join or last;
+
+      (pop @join)->join;
+   }
+}
+
 =item cf::lock_wait $string
 
 Wait until the given lock is available. See cf::lock_acquire. 
@@ -422,9 +502,13 @@
 
 =item cf::get_slot $time[, $priority[, $name]]
 
-Allocate $time seconds of blocking CPU time at priority C<$priority>:
-This call blocks and returns only when you have at least C<$time> seconds
-of cpu time till the next tick. The slot is only valid till the next cede.
+Allocate $time seconds of blocking CPU time at priority C<$priority>
+(default: 0):  This call blocks and returns only when you have at least
+C<$time> seconds of cpu time till the next tick. The slot is only valid
+till the next cede.
+
+Background jobs should use a priority les than zero, interactive jobs
+should use 100 or more.
 
 The optional C<$name> can be used to identify the job to run. It might be
 used for statistical purposes and should identify the same time-class.
@@ -514,13 +598,13 @@
 sub sync_job(&) {
    my ($job) = @_;
 
-   if ($Coro::current == $Coro::main) {
+   if (in_main) {
       my $time = AE::time;
 
       # this is the main coro, too bad, we have to block
       # till the operation succeeds, freezing the server :/
       
-      LOG llevError, Carp::longmess "sync job";#d#
+      #LOG llevError, Carp::longmess "sync job";#d#
 
       my $freeze_guard = freeze_mainloop;
 
@@ -530,7 +614,7 @@
       (async {
          $Coro::current->desc ("sync job coro");
          @res = eval { $job->() };
-         warn $@ if $@;
+         error $@ if $@;
          undef $busy;
       })->prio (Coro::PRIO_MAX);
 
@@ -574,7 +658,7 @@
    $coro
 }
 
-=item fork_call { }, $args
+=item fork_call { }, @args
 
 Executes the given code block with the given arguments in a seperate
 process, returning the results. Everything must be serialisable with
@@ -583,6 +667,10 @@
 
 =cut
 
+sub post_fork {
+   reset_signals;
+}
+
 sub fork_call(&@) {
    my ($cb, @args) = @_;
 
@@ -591,9 +679,9 @@
    # TODO: investigate and fix (likely this will be rather laborious)
 
    my @res = Coro::Util::fork_eval {
-      reset_signals;
+      cf::post_fork;
       &$cb
-   }, @args;
+   } @args;
 
    wantarray ? @res : $res[-1]
 }
@@ -653,6 +741,9 @@
 =cut
 
 sub db_table($) {
+   cf::error "db_get called from main context"
+      if $Coro::current == $Coro::main;
+
    my ($name) = @_;
    my $db = BDB::db_create $DB_ENV;
 
@@ -672,20 +763,19 @@
 our $DB;
 
 sub db_init {
-   cf::sync_job {
-      $DB ||= db_table "db";
-   };
+   $DB ||= db_table "db";
 }
 
 sub db_get($$) {
    my $key = "$_[0]/$_[1]";
 
-   cf::sync_job {
-      BDB::db_get $DB, undef, $key, my $data;
+   cf::error "db_get called from main context"
+      if $Coro::current == $Coro::main;
 
-      $! ? ()
-         : $data
-   }
+   BDB::db_get $DB, undef, $key, my $data;
+
+   $! ? ()
+      : $data
 }
 
 sub db_put($$$) {
@@ -723,8 +813,7 @@
       my $md5;
 
       for (0 .. $#$src) {
-         0 <= aio_load $src->[$_], $data[$_]
-            or Carp::croak "$src->[$_]: $!";
+         $data[$_] = load_file $src->[$_];
       }
 
       # if processing is expensive, check
@@ -751,7 +840,7 @@
       my $data = $process->(\@data);
       my $t2 = Time::HiRes::time;
 
-      warn "cache: '$id' processed in ", $t2 - $t1, "s\n";
+      info "cache: '$id' processed in ", $t2 - $t1, "s\n";
 
       db_put cache => "$id/data", $data;
       db_put cache => "$id/md5" , $md5;
@@ -771,7 +860,7 @@
 
 sub datalog($@) {
   my ($type, %kv) = @_;
-  warn "DATALOG ", JSON::XS->new->ascii->encode ({ %kv, type => $type });
+  info "DATALOG ", JSON::XS->new->ascii->encode ({ %kv, type => $type });
 }
 
 =back
@@ -976,11 +1065,11 @@
          _attach_cb $registry, $cb_id{$type}, $prio, shift @arg;
 
       } elsif (ref $type) {
-         warn "attaching objects not supported, ignoring.\n";
+         error "attaching objects not supported, ignoring.\n";
 
       } else {
          shift @arg;
-         warn "attach argument '$type' not supported, ignoring.\n";
+         error "attach argument '$type' not supported, ignoring.\n";
       }
    }
 }
@@ -1000,7 +1089,7 @@
 
       $obj->{$name} = \%arg;
    } else {
-      warn "object uses attachment '$name' which is not available, postponing.\n";
+      info "object uses attachment '$name' which is not available, postponing.\n";
    }
 
    $obj->{_attachment}{$name} = undef;
@@ -1069,8 +1158,7 @@
       eval { &{$_->[1]} };
 
       if ($@) {
-         warn "$@";
-         warn "... while processing $EVENT[$event][0](@_) event, skipping processing altogether.\n";
+         error "$@", "... while processing $EVENT[$event][0](@_) event, skipping processing altogether.\n";
          override;
       }
 
@@ -1159,7 +1247,7 @@
             _attach $registry, $klass, @attach;
          }
       } else {
-         warn "object uses attachment '$name' that is not available, postponing.\n";
+         info "object uses attachment '$name' that is not available, postponing.\n";
       }
    }
 }
@@ -1196,8 +1284,8 @@
    sync_job {
       if (length $$rdata) {
          utf8::decode (my $decname = $filename);
-         warn sprintf "saving %s (%d,%d)\n",
-                      $decname, length $$rdata, scalar @$objs
+         trace sprintf "saving %s (%d,%d)\n",
+                       $decname, length $$rdata, scalar @$objs
             if $VERBOSE_IO;
 
          if (my $fh = aio_open "$filename~", O_WRONLY | O_CREAT, 0600) {
@@ -1230,7 +1318,7 @@
             $filename =~ s%/[^/]+$%%;
             aio_pathsync $filename if $cf::USE_FSYNC;
          } else {
-            warn "unable to save objects: $filename~: $!\n";
+            error "unable to save objects: $filename~: $!\n";
          }
       } else {
          aio_unlink $filename;
@@ -1264,8 +1352,8 @@
    }
 
    utf8::decode (my $decname = $filename);
-   warn sprintf "loading %s (%d,%d)\n",
-                $decname, length $data, scalar @{$av || []}
+   trace sprintf "loading %s (%d,%d)\n",
+                 $decname, length $data, scalar @{$av || []}
       if $VERBOSE_IO;
 
    ($data, $av)
@@ -1368,7 +1456,7 @@
             if $reply;
 
       } else {
-         warn "player " . ($pl->ob->name) . " sent unparseable ext message: <$buf>\n";
+         error "player " . ($pl->ob->name) . " sent unparseable ext message: <$buf>\n";
       }
 
       cf::override;
@@ -1389,6 +1477,8 @@
 }
 
 sub load_extensions {
+   info "loading extensions...";
+
    cf::sync_job {
       my %todo;
 
@@ -1416,7 +1506,7 @@
             if $source =~ /\A#!.*?perl.*?#\s*(.*)$/m;
 
          $ext{source} =
-            "package $pkg; use 5.10.0; use strict 'vars', 'subs'; use utf8;\n"
+            "package $pkg; use common::sense;\n"
             . "#line 1 \"$path\"\n{\n"
             . $source
             . "\n};\n1";
@@ -1438,12 +1528,12 @@
                   unless exists $done{$_};
             }
 
-            warn "... pass $pass, loading '$k' into '$v->{pkg}'\n";
+            trace "... pass $pass, loading '$k' into '$v->{pkg}'\n";
 
             my $active = eval $v->{source};
 
             if (length $@) {
-               warn "$v->{path}: $@\n";
+               error "$v->{path}: $@\n";
 
                cf::cleanup "mandatory extension '$k' failed to load, exiting."
                   if exists $v->{meta}{mandatory};
@@ -1455,7 +1545,7 @@
                push @EXTS, $v->{pkg};
                $progress = 1;
 
-               warn "$v->{base}: extension inactive.\n"
+               info "$v->{base}: extension inactive.\n"
                   unless $active;
             }
          }
@@ -1467,6 +1557,8 @@
                cf::cleanup "mandatory extension '$k' has unresolved dependencies, exiting."
                   if exists $v->{meta}{mandatory};
             }
+
+            last;
          }
       }
    };
@@ -1634,10 +1726,13 @@
    $pl->{deny_save} = 1;
    $pl->password ("*"); # this should lock out the player until we have nuked the dir
 
-   $pl->invoke (cf::EVENT_PLAYER_LOGOUT, 1) if $pl->active;
+   $pl->invoke (cf::EVENT_PLAYER_LOGOUT, 1) if $pl->ns;
    $pl->deactivate;
+
    my $killer = cf::arch::get "killer_quit"; $pl->killer ($killer); $killer->destroy;
-   $pl->invoke (cf::EVENT_PLAYER_QUIT);
+   $pl->invoke (cf::EVENT_PLAYER_QUIT) if $pl->ns;
+   ext::highscore::check ($pl->ob);
+
    $pl->ns->destroy if $pl->ns;
 
    my $path = playerdir $pl;
@@ -1813,20 +1908,7 @@
 
    my $lock = cf::lock_acquire "generate_random_map"; # the random map generator is NOT reentrant ATM
 
-   # mit "rum" bekleckern, nicht
-   $self->_create_random_map (
-      $rmp->{wallstyle}, $rmp->{wall_name}, $rmp->{floorstyle}, $rmp->{monsterstyle},
-      $rmp->{treasurestyle}, $rmp->{layoutstyle}, $rmp->{doorstyle}, $rmp->{decorstyle}, $rmp->{miningstyle},
-      $rmp->{origin_map}, $rmp->{final_map}, $rmp->{exitstyle}, $rmp->{this_map},
-      $rmp->{exit_on_final_map},
-      $rmp->{xsize}, $rmp->{ysize},
-      $rmp->{expand2x}, $rmp->{layoutoptions1}, $rmp->{layoutoptions2}, $rmp->{layoutoptions3},
-      $rmp->{symmetry}, $rmp->{difficulty}, $rmp->{difficulty_given}, $rmp->{difficulty_increase},
-      $rmp->{dungeon_level}, $rmp->{dungeon_depth}, $rmp->{decoroptions}, $rmp->{orientation},
-      $rmp->{origin_y}, $rmp->{origin_x}, $rmp->{random_seed}, $rmp->{total_map_hp},
-      $rmp->{map_layout_style}, $rmp->{treasureoptions}, $rmp->{symmetry_used},
-      (cf::region::find $rmp->{region}), $rmp->{custom}
-   )
+   $self->_create_random_map ($rmp);
 }
 
 =item cf::map->register ($regex, $prio)
@@ -1841,7 +1923,6 @@
    my (undef, $regex, $prio) = @_;
    my $pkg = caller;
 
-   no strict;
    push @{"$pkg\::ISA"}, __PACKAGE__;
 
    $EXT_MAP{$pkg} = [$prio, qr<$regex>];
@@ -1863,7 +1944,7 @@
 sub normalise {
    my ($path, $base) = @_;
 
-   $path = "$path"; # make sure its a string
+   $path = "$path"; # make sure it's a string
 
    $path =~ s/\.map$//;
 
@@ -1888,7 +1969,6 @@
    }
 
    for ($path) {
-      redo if s{//}{/};
       redo if s{/\.?/}{/};
       redo if s{/[^/]+/\.\./}{/};
    }
@@ -1912,10 +1992,11 @@
       }
    }
 
-   Carp::cluck "unable to resolve path '$path' (base '$base').";
+   Carp::cluck "unable to resolve path '$path' (base '$base')";
    ()
 }
 
+# may re-bless or do other evil things
 sub init {
    my ($self) = @_;
 
@@ -2045,6 +2126,8 @@
 sub find {
    my ($path, $origin) = @_;
 
+   cf::cede_to_tick;
+
    $path = normalise $path, $origin && $origin->path;
 
    my $guard1 = cf::lock_acquire "map_data:$path";#d#remove
@@ -2095,26 +2178,28 @@
       $self->pre_load;
       cf::cede_to_tick;
 
-      my $f = new_from_file cf::object::thawer $self->{load_path};
-      $f->skip_block;
-      $self->_load_objects ($f)
-         or return;
+      if (exists $self->{load_path}) {
+         my $f = new_from_file cf::object::thawer $self->{load_path};
+         $f->skip_block;
+         $self->_load_objects ($f)
+            or return;
 
-      $self->post_load_original
-         if delete $self->{load_original};
+         $self->post_load_original
+            if delete $self->{load_original};
 
-      if (my $uniq = $self->uniq_path) {
-         utf8::encode $uniq;
-         unless (aio_stat $uniq) {
-            if (my $f = new_from_file cf::object::thawer $uniq) {
-               $self->clear_unique_items;
-               $self->_load_objects ($f);
-               $f->resolve_delayed_derefs;
+         if (my $uniq = $self->uniq_path) {
+            utf8::encode $uniq;
+            unless (aio_stat $uniq) {
+               if (my $f = new_from_file cf::object::thawer $uniq) {
+                  $self->clear_unique_items;
+                  $self->_load_objects ($f);
+                  $f->resolve_delayed_derefs;
+               }
             }
          }
-      }
 
-      $f->resolve_delayed_derefs;
+         $f->resolve_delayed_derefs;
+      }
 
       cf::cede_to_tick;
       # now do the right thing for maps
@@ -2138,6 +2223,8 @@
    }
 
    $self->post_load;
+
+   1
 }
 
 # customize the map for a given player, i.e.
@@ -2185,16 +2272,19 @@
 sub find_sync {
    my ($path, $origin) = @_;
 
-   cf::sync_job { find $path, $origin }
+   return cf::LOG cf::llevError | cf::logBacktrace, "do_find_sync"
+      if $Coro::current == $Coro::main;
+
+   find $path, $origin
 }
 
 sub do_load_sync {
    my ($map) = @_;
 
-   cf::LOG cf::llevDebug | cf::logBacktrace, "do_load_sync"
+   return cf::LOG cf::llevError | cf::logBacktrace, "do_load_sync"
       if $Coro::current == $Coro::main;
 
-   cf::sync_job { $map->load };
+   $map->load;
 }
 
 our %MAP_PREFETCH;
@@ -2316,7 +2406,7 @@
 
    return if $self->players;
 
-   warn "resetting map ", $self->path, "\n";
+   cf::trace "resetting map ", $self->path, "\n";
 
    $self->in_memory (cf::MAP_SWAPPED);
 
@@ -2691,7 +2781,7 @@
    my ($self, $path, $x, $y, $check, $done) = @_;
 
    if ($self->{_link_recursion} >= $MAX_LINKS) {
-      warn "FATAL: link recursion exceeded, ", $self->name, " goto $path $x $y, redirecting.";
+      error "FATAL: link recursion exceeded, ", $self->name, " goto $path $x $y, redirecting.";
       $self->failmsg ("Something went wrong inside the server - please contact an administrator!");
       ($path, $x, $y) = @$EMERGENCY_POSITION;
    }
@@ -2849,7 +2939,7 @@
                        . "Please report this to the dungeon master!",
                          cf::NDI_UNIQUE | cf::NDI_RED);
 
-         warn "ERROR in enter_exit: $@";
+         error "ERROR in enter_exit: $@";
          $self->leave_link;
       }
    })->prio (1);
@@ -3172,7 +3262,7 @@
             if $reply;
 
       } else {
-         warn "client " . ($ns->pl ? $ns->pl->ob->name : $ns->host) . " sent unparseable exti message: <$buf>\n";
+         error "client " . ($ns->pl ? $ns->pl->ob->name : $ns->host) . " sent unparseable exti message: <$buf>\n";
       }
 
       cf::override;
@@ -3263,7 +3353,6 @@
    ["cf::player"         => qw(peaceful send_msg)],
    ["cf::map"            => qw(trigger)],
 ) {
-   no strict 'refs';
    my ($pkg, @funs) = @$_;
    *{"safe::$pkg\::$_"} = $safe_hole->wrap (\&{"$pkg\::$_"})
       for @funs;
@@ -3312,9 +3401,9 @@
    }
 
    if ($@) {
-      warn "$@";
-      warn "while executing safe code '$code'\n";
-      warn "with arguments " . (join " ", %vars) . "\n";
+      warn "$@",
+           "while executing safe code '$code'\n",
+           "with arguments " . (join " ", %vars) . "\n";
    }
 
    wantarray ? @res : $res[0]
@@ -3358,13 +3447,9 @@
 
    my $enc = JSON::XS->new->utf8->canonical->relaxed;
 
-   warn "loading facedata from $path\n";
-
-   my $facedata;
-   0 < aio_load $path, $facedata
-      or die "$path: $!";
+   trace "loading facedata from $path\n";
 
-   $facedata = Coro::Storable::thaw $facedata;
+   my $facedata = decode_storable load_file $path;
 
    $facedata->{version} == 2
       or cf::cleanup "$path: version mismatch, cannot proceed.";
@@ -3388,6 +3473,7 @@
          cf::face::set_magicmap   $idx, $info->{magicmap};
          cf::face::set_data $idx, 0, $info->{data32}, $info->{hash32};
          cf::face::set_data $idx, 1, $info->{data64}, $info->{hash64};
+         cf::face::set_data $idx, 2, $info->{glyph} , $info->{glyph} ;
 
          cf::cede_to_tick;
       }
@@ -3402,7 +3488,7 @@
             cf::face::set_smooth      $idx, $smooth;
             cf::face::set_smoothlevel $idx, $info->{smoothlevel};
          } else {
-            warn "smooth face '$info->{smooth}' not found for face '$face'";
+            error "smooth face '$info->{smooth}' not found for face '$face'";
          }
 
          cf::cede_to_tick;
@@ -3490,12 +3576,9 @@
 }
 
 sub reload_sound {
-   warn "loading sound config from $DATADIR/sound\n";
+   trace "loading sound config from $DATADIR/sound\n";
 
-   0 < Coro::AIO::aio_load "$DATADIR/sound", my $data
-      or die "$DATADIR/sound $!";
-
-   my $soundconf = JSON::XS->new->utf8->relaxed->decode ($data);
+   my $soundconf = JSON::XS->new->utf8->relaxed->decode (load_file "$DATADIR/sound");
 
    for (0 .. SOUND_CAST_SPELL_0 - 1) {
       my $sound = $soundconf->{compat}[$_]
@@ -3513,25 +3596,25 @@
 }
 
 sub reload_resources {
-   warn "reloading resource files...\n";
+   trace "reloading resource files...\n";
 
+   reload_exp_table;
+   reload_materials;
    reload_facedata;
    reload_sound;
    reload_archetypes;
    reload_regions;
    reload_treasures;
 
-   warn "finished reloading resource files\n";
+   trace "finished reloading resource files\n";
 }
 
 sub reload_config {
-   warn "reloading config file...\n";
-
-   open my $fh, "<:utf8", "$CONFDIR/config"
-      or return;
+   trace "reloading config file...\n";
 
-   local $/;
-   *CFG = YAML::XS::Load scalar <$fh>;
+   my $config = load_file "$CONFDIR/config";
+   utf8::decode $config;
+   *CFG = decode_yaml $config;
 
    $EMERGENCY_POSITION = $CFG{emergency_position} || ["/world/world_104_115", 49, 38];
 
@@ -3545,8 +3628,6 @@
       };
       warn $@ if $@;
    }
-
-   warn "finished reloading resource files\n";
 }
 
 sub pidfile() {
@@ -3569,11 +3650,11 @@
 }
 
 sub main_loop {
-   warn "EV::loop starting\n";
+   trace "EV::loop starting\n";
    if (1) {
       EV::loop;
    }
-   warn "EV::loop returned\n";
+   trace "EV::loop returned\n";
    goto &main_loop unless $REALLY_UNLOOP;
 }
 
@@ -3581,7 +3662,7 @@
    cf::init_globals; # initialise logging
 
    LOG llevInfo, "Welcome to Deliantra, v" . VERSION;
-   LOG llevInfo, "Copyright (C) 2005-2008 Marc Alexander Lehmann / Robin Redeker / the Deliantra team.";
+   LOG llevInfo, "Copyright (C) 2005-2011 Marc Alexander Lehmann / Robin Redeker / the Deliantra team.";
    LOG llevInfo, "Copyright (C) 1994 Mark Wedel.";
    LOG llevInfo, "Copyright (C) 1992 Frank Tore Johansen.";
 
@@ -3599,13 +3680,13 @@
    evthread_start IO::AIO::poll_fileno;
 
    cf::sync_job {
-      cf::init_experience;
+      cf::incloader::init ();
+
       cf::init_anim;
       cf::init_attackmess;
       cf::init_dynamic;
 
       cf::load_settings;
-      cf::load_materials;
 
       reload_resources;
       reload_config;
@@ -3627,13 +3708,18 @@
       use POSIX ();
       POSIX::close delete $ENV{LOCKUTIL_LOCK_FD} if exists $ENV{LOCKUTIL_LOCK_FD};
 
-      (pop @POST_INIT)->(0) while @POST_INIT;
+      cf::_post_init 0;
    };
 
    cf::object::thawer::errors_are_fatal 0;
-   warn "parse errors in files are no longer fatal from this point on.\n";
+   info "parse errors in files are no longer fatal from this point on.\n";
+
+   my $free_main; $free_main = EV::idle sub {
+      undef $free_main;
+      undef &main; # free gobs of memory :)
+   };
 
-   main_loop;
+   goto &main_loop;
 }
 
 #############################################################################
@@ -3682,7 +3768,7 @@
    aio_rename "$RUNTIMEFILE~", $RUNTIMEFILE
       and return;
 
-   warn sprintf "runtime file written (%gs).\n", AE::time - $t0;
+   trace sprintf "runtime file written (%gs).\n", AE::time - $t0;
 
    1
 }
@@ -3704,7 +3790,7 @@
    my $value = uuid_seq uuid_cur;
 
    unless ($value) {
-      warn "cowardly refusing to write zero uuid value!\n";
+      info "cowardly refusing to write zero uuid value!\n";
       return;
    }
 
@@ -3724,7 +3810,7 @@
    aio_rename "$uuid~", $uuid
       and return;
 
-   warn "uuid file written ($value).\n";
+   trace "uuid file written ($value).\n";
 
    1
 
@@ -3740,55 +3826,77 @@
 sub emergency_save() {
    my $freeze_guard = cf::freeze_mainloop;
 
-   warn "emergency_perl_save: enter\n";
+   info "emergency_perl_save: enter\n";
+
+   # this is a trade-off: we want to be very quick here, so
+   # save all maps without fsync, and later call a global sync
+   # (which in turn might be very very slow)
+   local $USE_FSYNC = 0;
 
    cf::sync_job {
-      # this is a trade-off: we want to be very quick here, so
-      # save all maps without fsync, and later call a global sync
-      # (which in turn might be very very slow)
-      local $USE_FSYNC = 0;
+      cf::write_runtime_sync; # external watchdog should not bark
 
       # use a peculiar iteration method to avoid tripping on perl
       # refcount bugs in for. also avoids problems with players
       # and maps saved/destroyed asynchronously.
-      warn "emergency_perl_save: begin player save\n";
+      info "emergency_perl_save: begin player save\n";
       for my $login (keys %cf::PLAYER) {
          my $pl = $cf::PLAYER{$login} or next;
          $pl->valid or next;
          delete $pl->{unclean_save}; # not strictly necessary, but cannot hurt
          $pl->save;
       }
-      warn "emergency_perl_save: end player save\n";
+      info "emergency_perl_save: end player save\n";
+
+      cf::write_runtime_sync; # external watchdog should not bark
 
-      warn "emergency_perl_save: begin map save\n";
+      info "emergency_perl_save: begin map save\n";
       for my $path (keys %cf::MAP) {
          my $map = $cf::MAP{$path} or next;
          $map->valid or next;
          $map->save;
       }
-      warn "emergency_perl_save: end map save\n";
+      info "emergency_perl_save: end map save\n";
 
-      warn "emergency_perl_save: begin database checkpoint\n";
+      cf::write_runtime_sync; # external watchdog should not bark
+
+      info "emergency_perl_save: begin database checkpoint\n";
       BDB::db_env_txn_checkpoint $DB_ENV;
-      warn "emergency_perl_save: end database checkpoint\n";
+      info "emergency_perl_save: end database checkpoint\n";
 
-      warn "emergency_perl_save: begin write uuid\n";
+      info "emergency_perl_save: begin write uuid\n";
       write_uuid_sync 1;
-      warn "emergency_perl_save: end write uuid\n";
-   };
+      info "emergency_perl_save: end write uuid\n";
+
+      cf::write_runtime_sync; # external watchdog should not bark
 
-   warn "emergency_perl_save: starting sync()\n";
-   IO::AIO::aio_sync sub {
-      warn "emergency_perl_save: finished sync()\n";
+      trace "emergency_perl_save: syncing database to disk";
+      BDB::db_env_txn_checkpoint $DB_ENV;
+
+      info "emergency_perl_save: starting sync\n";
+      IO::AIO::aio_sync sub {
+         info "emergency_perl_save: finished sync\n";
+      };
+
+      cf::write_runtime_sync; # external watchdog should not bark
+
+      trace "emergency_perl_save: flushing outstanding aio requests";
+      while (IO::AIO::nreqs || BDB::nreqs) {
+         Coro::EV::timer_once 0.01; # let the sync_job do it's thing
+      }
+
+      cf::write_runtime_sync; # external watchdog should not bark
    };
 
-   warn "emergency_perl_save: leave\n";
+   info "emergency_perl_save: leave\n";
 }
 
 sub post_cleanup {
    my ($make_core) = @_;
 
-   warn Carp::longmess "post_cleanup backtrace"
+   IO::AIO::flush;
+
+   error Carp::longmess "post_cleanup backtrace"
       if $make_core;
 
    my $fh = pidfile;
@@ -3822,8 +3930,8 @@
 
 sub do_reload_perl() {
    # can/must only be called in main
-   if (in_main) {
-      warn "can only reload from main coroutine";
+   unless (in_main) {
+      error "can only reload from main coroutine";
       return;
    }
 
@@ -3832,56 +3940,45 @@
    my $t1 = AE::time;
 
    while ($RELOAD) {
-      warn "reloading...";
+      cf::get_slot 0.1, -1, "reload_perl";
+      info "perl_reload: reloading...";
 
-      warn "entering sync_job";
+      trace "perl_reload: entering sync_job";
 
       cf::sync_job {
-         cf::write_runtime_sync; # external watchdog should not bark
-         cf::emergency_save;
-         cf::write_runtime_sync; # external watchdog should not bark
-
-         warn "syncing database to disk";
-         BDB::db_env_txn_checkpoint $DB_ENV;
-
-         # if anything goes wrong in here, we should simply crash as we already saved
-
-         warn "flushing outstanding aio requests";
-         while (IO::AIO::nreqs || BDB::nreqs) {
-            Coro::EV::timer_once 0.01; # let the sync_job do it's thing
-         }
+         #cf::emergency_save;
 
-         warn "cancelling all extension coros";
+         trace "perl_reload: cancelling all extension coros";
          $_->cancel for values %EXT_CORO;
          %EXT_CORO = ();
 
-         warn "removing commands";
+         trace "perl_reload: removing commands";
          %COMMAND = ();
 
-         warn "removing ext/exti commands";
+         trace "perl_reload: removing ext/exti commands";
          %EXTCMD  = ();
          %EXTICMD = ();
 
-         warn "unloading/nuking all extensions";
+         trace "perl_reload: unloading/nuking all extensions";
          for my $pkg (@EXTS) {
-            warn "... unloading $pkg";
+            trace "... unloading $pkg";
 
             if (my $cb = $pkg->can ("unload")) {
                eval {
                   $cb->($pkg);
                   1
-               } or warn "$pkg unloaded, but with errors: $@";
+               } or error "$pkg unloaded, but with errors: $@";
             }
 
-            warn "... clearing $pkg";
+            trace "... clearing $pkg";
             clear_package $pkg;
          }
 
-         warn "unloading all perl modules loaded from $LIBDIR";
+         trace "perl_reload: unloading all perl modules loaded from $LIBDIR";
          while (my ($k, $v) = each %INC) {
             next unless $v =~ /^\Q$LIBDIR\E\/.*\.pm$/;
 
-            warn "... unloading $k";
+            trace "... unloading $k";
             delete $INC{$k};
 
             $k =~ s/\.pm$//;
@@ -3894,11 +3991,11 @@
             clear_package $k;
          }
 
-         warn "getting rid of safe::, as good as possible";
+         trace "perl_reload: getting rid of safe::, as good as possible";
          clear_package "safe::$_"
             for qw(cf::attachable cf::object cf::object::player cf::client cf::player cf::map cf::party cf::region);
 
-         warn "unloading cf.pm \"a bit\"";
+         trace "perl_reload: unloading cf.pm \"a bit\"";
          delete $INC{"cf.pm"};
          delete $INC{"cf/$_.pm"} for @EXTRA_MODULES;
 
@@ -3906,44 +4003,42 @@
          # and global variables created in xs
          #clear_package __PACKAGE__;
 
-         warn "unload completed, starting to reload now";
+         info "perl_reload: unload completed, starting to reload now";
 
-         warn "reloading cf.pm";
+         trace "perl_reload: reloading cf.pm";
          require cf;
          cf::_connect_to_perl_1;
 
-         warn "loading config and database again";
+         trace "perl_reload: loading config and database again";
          cf::reload_config;
 
-         warn "loading extensions";
+         trace "perl_reload: loading extensions";
          cf::load_extensions;
 
          if ($REATTACH_ON_RELOAD) {
-            warn "reattaching attachments to objects/players";
+            trace "perl_reload: reattaching attachments to objects/players";
             _global_reattach; # objects, sockets
-            warn "reattaching attachments to maps";
+            trace "perl_reload: reattaching attachments to maps";
             reattach $_ for values %MAP;
-            warn "reattaching attachments to players";
+            trace "perl_reload: reattaching attachments to players";
             reattach $_ for values %PLAYER;
          }
 
-         warn "running post_init jobs";
-         (pop @POST_INIT)->(1) while @POST_INIT;
+         cf::_post_init 1;
 
-         warn "leaving sync_job";
+         trace "perl_reload: leaving sync_job";
 
          1
       } or do {
-         warn $@;
-         cf::cleanup "error while reloading, exiting.";
+         error $@;
+         cf::cleanup "perl_reload: error, exiting.";
       };
 
-      warn "reloaded";
       --$RELOAD;
    }
 
    $t1 = AE::time - $t1;
-   warn "reload completed in ${t1}s\n";
+   info "perl_reload: completed in ${t1}s\n";
 };
 
 our $RELOAD_WATCHER; # used only during reload
@@ -3974,14 +4069,14 @@
    }
 };
 
-unshift @INC, $LIBDIR;
+#############################################################################
 
 my $bug_warning = 0;
 
 our @WAIT_FOR_TICK;
 our @WAIT_FOR_TICK_BEGIN;
 
-sub wait_for_tick {
+sub wait_for_tick() {
    return Coro::cede if tick_inhibit || $Coro::current == $Coro::main;
 
    my $signal = new Coro::Signal;
@@ -3989,7 +4084,7 @@
    $signal->wait;
 }
 
-sub wait_for_tick_begin {
+sub wait_for_tick_begin() {
    return Coro::cede if tick_inhibit || $Coro::current == $Coro::main;
 
    my $signal = new Coro::Signal;
@@ -4013,7 +4108,7 @@
       Coro::async_pool {
          $Coro::current->{desc} = "runtime saver";
          write_runtime_sync
-            or warn "ERROR: unable to write runtime file: $!";
+            or error "ERROR: unable to write runtime file: $!";
       };
    }
 
@@ -4031,7 +4126,7 @@
       if ($NEXT_TICK) {
          my $jitter = $TICK_START - $NEXT_TICK;
          $JITTER = $JITTER * 0.75 + $jitter * 0.25;
-         warn "jitter $JITTER\n";#d#
+         debug "jitter $JITTER\n";#d#
       }
    }
 }
@@ -4086,15 +4181,20 @@
    undef $AnyEvent::AIO::WATCHER;
 }
 
-my $_log_backtrace;
+our $_log_backtrace;
+our $_log_backtrace_last;
 
 sub _log_backtrace {
    my ($msg, @addr) = @_;
 
-   $msg =~ s/\n//;
+   $msg =~ s/\n$//;
 
+   if ($_log_backtrace_last eq $msg) {
+      LOG llevInfo, "[ABT] $msg\n";
+      LOG llevInfo, "[ABT] [duplicate, suppressed]\n";
    # limit the # of concurrent backtraces
-   if ($_log_backtrace < 2) {
+   } elsif ($_log_backtrace < 2) {
+      $_log_backtrace_last = $msg;
       ++$_log_backtrace;
       my $perl_bt = Carp::longmess $msg;
       async {
@@ -4124,7 +4224,7 @@
       };
    } else {
       LOG llevInfo, "[ABT] $msg\n";
-      LOG llevInfo, "[ABT] [suppressed]\n";
+      LOG llevInfo, "[ABT] [overload, suppressed]\n";
    }
 }