--- deliantra/server/lib/cf.pm	2010/04/17 02:39:46	1.523
+++ deliantra/server/lib/cf.pm	2010/05/18 21:30:16	1.553
@@ -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 = ();
 
@@ -108,10 +108,13 @@
 our $PIDFILE     = "$LOCALDIR/pid";
 our $RUNTIMEFILE = "$LOCALDIR/runtime";
 
-our %RESOURCE;
+our %RESOURCE; # unused
+
+our $OUTPUT_RATE_MIN =    3000;
+our $OUTPUT_RATE_MAX = 1000000;
 
-our $OUTPUT_RATE_MIN =   4000;
-our $OUTPUT_RATE_MAX = 100000;
+our $MAX_LINKS       = 32; # how many chained exits to follow
+our $VERBOSE_IO      = 1;
 
 our $TICK = MAX_TIME * 1e-6; # this is a CONSTANT(!)
 our $NEXT_RUNTIME_WRITE; # when should the runtime file be written
@@ -123,7 +126,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;
 
@@ -232,9 +235,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
@@ -251,6 +259,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 "", @_;
 
@@ -259,16 +273,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#
 
@@ -345,12 +359,24 @@
 sub encode_json($) { $json_coder->encode ($_[0]) }
 sub decode_json($) { $json_coder->decode ($_[0]) }
 
+=item $ref = cf::yaml_load $scalar
+
+Same as YAML::XS::Load, but doesn't leak, because it forks (and thus blocks).
+
+=cut
+
+sub fork_call(&@);
+
+sub yaml_load($) {
+   fork_call { YAML::XS::Load $_[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
@@ -359,6 +385,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. 
@@ -511,13 +554,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;
 
@@ -527,7 +570,7 @@
       (async {
          $Coro::current->desc ("sync job coro");
          @res = eval { $job->() };
-         warn $@ if $@;
+         error $@ if $@;
          undef $busy;
       })->prio (Coro::PRIO_MAX);
 
@@ -571,7 +614,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
@@ -580,6 +623,10 @@
 
 =cut
 
+sub post_fork {
+   reset_signals;
+}
+
 sub fork_call(&@) {
    my ($cb, @args) = @_;
 
@@ -588,9 +635,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]
 }
@@ -650,6 +697,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;
 
@@ -669,20 +719,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($$$) {
@@ -748,7 +797,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;
@@ -768,7 +817,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
@@ -973,11 +1022,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";
       }
    }
 }
@@ -997,7 +1046,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;
@@ -1066,8 +1115,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;
       }
 
@@ -1156,7 +1204,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";
       }
    }
 }
@@ -1193,8 +1241,9 @@
    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) {
             aio_chmod $fh, SAVE_MODE;
@@ -1226,7 +1275,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;
@@ -1260,8 +1309,9 @@
    }
 
    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)
 }
@@ -1363,7 +1413,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;
@@ -1384,6 +1434,8 @@
 }
 
 sub load_extensions {
+   info "loading extensions...";
+
    cf::sync_job {
       my %todo;
 
@@ -1411,7 +1463,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";
@@ -1433,12 +1485,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};
@@ -1450,7 +1502,7 @@
                push @EXTS, $v->{pkg};
                $progress = 1;
 
-               warn "$v->{base}: extension inactive.\n"
+               info "$v->{base}: extension inactive.\n"
                   unless $active;
             }
          }
@@ -1629,11 +1681,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->ob->check_score;
-   $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;
@@ -1837,14 +1891,13 @@
    my (undef, $regex, $prio) = @_;
    my $pkg = caller;
 
-   no strict;
    push @{"$pkg\::ISA"}, __PACKAGE__;
 
    $EXT_MAP{$pkg} = [$prio, qr<$regex>];
 }
 
 # also paths starting with '/'
-$EXT_MAP{"cf::map"} = [0, qr{^(?=/)}];
+$EXT_MAP{"cf::map::wrap"} = [0, qr{^(?=/)}];
 
 sub thawer_merge {
    my ($self, $merge) = @_;
@@ -1859,7 +1912,7 @@
 sub normalise {
    my ($path, $base) = @_;
 
-   $path = "$path"; # make sure its a string
+   $path = "$path"; # make sure it's a string
 
    $path =~ s/\.map$//;
 
@@ -1884,7 +1937,6 @@
    }
 
    for ($path) {
-      redo if s{//}{/};
       redo if s{/\.?/}{/};
       redo if s{/[^/]+/\.\./}{/};
    }
@@ -1908,7 +1960,7 @@
       }
    }
 
-   Carp::cluck "unable to resolve path '$path' (base '$base').";
+   Carp::cluck "unable to resolve path '$path' (base '$base')";
    ()
 }
 
@@ -2041,6 +2093,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
@@ -2134,6 +2188,8 @@
    }
 
    $self->post_load;
+
+   1
 }
 
 # customize the map for a given player, i.e.
@@ -2164,6 +2220,7 @@
          or next;
       $neigh->load;
 
+      # now find the diagonal neighbours
       push @neigh,
          [$neigh->tile_path (($_ + 3) % 4), $neigh],
          [$neigh->tile_path (($_ + 1) % 4), $neigh];
@@ -2180,16 +2237,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;
@@ -2311,7 +2371,7 @@
 
    return if $self->players;
 
-   warn "resetting map ", $self->path, "\n";
+   cf::trace "resetting map ", $self->path, "\n";
 
    $self->in_memory (cf::MAP_SWAPPED);
 
@@ -2345,7 +2405,7 @@
 
       $self->unlink_save;
 
-      bless $self, "cf::map";
+      bless $self, "cf::map::wrap";
       delete $self->{deny_reset};
       $self->{deny_save} = 1;
       $self->reset_timeout (1);
@@ -2585,7 +2645,7 @@
 
 The player should be reasonably safe there for short amounts of time (e.g.
 for loading a map). You I<MUST> call C<leave_link> as soon as possible,
-though, as the palyer cannot control the character while it is on the link
+though, as the player cannot control the character while it is on the link
 map.
 
 Will never block.
@@ -2616,6 +2676,8 @@
 
    $self->deactivate_recursive;
 
+   ++$self->{_link_recursion};
+
    return if UNIVERSAL::isa $self->map, "ext::map_link";
 
    $self->{_link_pos} ||= [$self->map->{path}, $self->x, $self->y]
@@ -2656,13 +2718,16 @@
    return unless $self->contr->active;
 
    local $self->{_prev_pos} = $link_pos; # ugly hack for rent.ext
-   $self->enter_map ($map, $x, $y);
+   if ($self->enter_map ($map, $x, $y)) {
+      # entering was successful
+      delete $self->{_link_recursion};
+      # only activate afterwards, to support waiting in hooks
+      $self->activate_recursive;
+   }
 
-   # only activate afterwards, to support waiting in hooks
-   $self->activate_recursive;
 }
 
-=item $player_object->goto ($path, $x, $y[, $check->($map)[, $done->()]])
+=item $player_object->goto ($path, $x, $y[, $check->($map, $x, $y, $player)[, $done->($player)]])
 
 Moves the player to the given map-path and coordinates by first freezing
 her, loading and preparing them map, calling the provided $check callback
@@ -2680,6 +2745,12 @@
 sub cf::object::player::goto {
    my ($self, $path, $x, $y, $check, $done) = @_;
 
+   if ($self->{_link_recursion} >= $MAX_LINKS) {
+      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;
+   }
+
    # do generation counting so two concurrent goto's will be executed in-order
    my $gen = $self->{_goto_generation} = ++$GOTOGEN;
 
@@ -2712,7 +2783,7 @@
 
          if ($map) {
             $map = $map->customise_for ($self);
-            $map = $check->($map) if $check && $map;
+            $map = $check->($map, $x, $y, $self) if $check && $map;
          } else {
             $self->message ("The exit to '$path' is closed.", cf::NDI_UNIQUE | cf::NDI_RED);
          }
@@ -2730,7 +2801,7 @@
          $self->leave_link ($map, $x, $y);
       }
 
-      $done->() if $done;
+      $done->($self) if $done;
    })->prio (1);
 }
 
@@ -2833,7 +2904,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);
@@ -3156,7 +3227,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;
@@ -3247,7 +3318,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;
@@ -3296,9 +3366,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]
@@ -3342,10 +3412,9 @@
 
    my $enc = JSON::XS->new->utf8->canonical->relaxed;
 
-   warn "loading facedata from $path\n";
+   trace "loading facedata from $path\n";
 
-   my $facedata;
-   0 < aio_load $path, $facedata
+   0 < aio_load $path, my $facedata
       or die "$path: $!";
 
    $facedata = Coro::Storable::thaw $facedata;
@@ -3386,7 +3455,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;
@@ -3414,7 +3483,7 @@
             cf::face::set_data $idx, 0, $info->{data}, $info->{hash};
             cf::face::set_type $idx, $info->{type};
          } else {
-            $RESOURCE{$name} = $info;
+            $RESOURCE{$name} = $info; # unused
          }
 
          cf::cede_to_tick;
@@ -3426,26 +3495,6 @@
    1
 }
 
-cf::global->attach (on_resource_update => sub {
-   if (my $soundconf = $RESOURCE{"res/sound.conf"}) {
-      $soundconf = JSON::XS->new->utf8->relaxed->decode ($soundconf->{data});
-
-      for (0 .. SOUND_CAST_SPELL_0 - 1) {
-         my $sound = $soundconf->{compat}[$_]
-            or next;
-
-         my $face = cf::face::find "sound/$sound->[1]";
-         cf::sound::set $sound->[0] => $face;
-         cf::sound::old_sound_index $_, $face; # gcfclient-compat
-      }
-
-      while (my ($k, $v) = each %{$soundconf->{event}}) {
-         my $face = cf::face::find "sound/$v";
-         cf::sound::set $k => $face;
-      }
-   }
-});
-
 register_exticmd fx_want => sub {
    my ($ns, $want) = @_;
 
@@ -3493,27 +3542,53 @@
       or die "unable to load treasurelists\n";
 }
 
+sub reload_sound {
+   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);
+
+   for (0 .. SOUND_CAST_SPELL_0 - 1) {
+      my $sound = $soundconf->{compat}[$_]
+         or next;
+
+      my $face = cf::face::find "sound/$sound->[1]";
+      cf::sound::set $sound->[0] => $face;
+      cf::sound::old_sound_index $_, $face; # gcfclient-compat
+   }
+
+   while (my ($k, $v) = each %{$soundconf->{event}}) {
+      my $face = cf::face::find "sound/$v";
+      cf::sound::set $k => $face;
+   }
+}
+
 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";
+   trace "reloading config file...\n";
 
-   open my $fh, "<:utf8", "$CONFDIR/config"
-      or return;
+   0 < aio_load "$CONFDIR/config", my $config
+      or die "$CONFDIR/config: $!";
 
-   local $/;
-   *CFG = YAML::XS::Load scalar <$fh>;
+   utf8::decode $config;
+   *CFG = yaml_load $config;
 
-   $EMERGENCY_POSITION = $CFG{emergency_position} || ["/world/world_105_115", 5, 37];
+   $EMERGENCY_POSITION = $CFG{emergency_position} || ["/world/world_104_115", 49, 38];
 
    $cf::map::MAX_RESET     = $CFG{map_max_reset}     if exists $CFG{map_max_reset};
    $cf::map::DEFAULT_RESET = $CFG{map_default_reset} if exists $CFG{map_default_reset};
@@ -3525,8 +3600,6 @@
       };
       warn $@ if $@;
    }
-
-   warn "finished reloading resource files\n";
 }
 
 sub pidfile() {
@@ -3549,11 +3622,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;
 }
 
@@ -3561,7 +3634,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-2010 Marc Alexander Lehmann / Robin Redeker / the Deliantra team.";
    LOG llevInfo, "Copyright (C) 1994 Mark Wedel.";
    LOG llevInfo, "Copyright (C) 1992 Frank Tore Johansen.";
 
@@ -3579,13 +3652,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;
@@ -3607,13 +3680,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";
 
-   main_loop;
+   my $free_main; $free_main = EV::idle sub {
+      undef $free_main;
+      undef &main; # free gobs of memory :)
+   };
+
+   goto &main_loop;
 }
 
 #############################################################################
@@ -3662,7 +3740,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
 }
@@ -3684,7 +3762,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;
    }
 
@@ -3704,7 +3782,7 @@
    aio_rename "$uuid~", $uuid
       and return;
 
-   warn "uuid file written ($value).\n";
+   trace "uuid file written ($value).\n";
 
    1
 
@@ -3720,55 +3798,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";
 
-      warn "emergency_perl_save: begin map save\n";
+      cf::write_runtime_sync; # external watchdog should not bark
+
+      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";
+
+      cf::write_runtime_sync; # external watchdog should not bark
 
-      warn "emergency_perl_save: begin database checkpoint\n";
+      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
+
+      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";
+      };
 
-   warn "emergency_perl_save: starting sync()\n";
-   IO::AIO::aio_sync sub {
-      warn "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;
@@ -3802,8 +3902,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;
    }
 
@@ -3812,56 +3912,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;
+         #cf::emergency_save;
 
-         # 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
-         }
-
-         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$//;
@@ -3874,11 +3963,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;
 
@@ -3886,44 +3975,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
@@ -3954,14 +4041,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;
@@ -3969,7 +4056,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;
@@ -3993,7 +4080,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: $!";
       };
    }
 
@@ -4011,7 +4098,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#
       }
    }
 }
@@ -4066,15 +4153,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 {
@@ -4104,7 +4196,7 @@
       };
    } else {
       LOG llevInfo, "[ABT] $msg\n";
-      LOG llevInfo, "[ABT] [suppressed]\n";
+      LOG llevInfo, "[ABT] [overload, suppressed]\n";
    }
 }