Enhance Lua debugging output.

Don't use "debug" as the name of a function to conditionally write debug
messages: "debug" is a Luau built-in library, and assigning that name locally
would shadow the builtin. Use "dbg" instead.

Recast fiber.print_all() as fiber.format_all() that returns a string; then
print_all() is simply print(format_all()). This refactoring allows us to use
dbg(format_all()) as well.

Add a couple new dbg() messages at fiber state changes.

4 files changed, 50 insertions, 40 deletions

diff --git a/indra/newview/scripts/lua/ErrorQueue.lua b/indra/newview/scripts/lua/ErrorQueue.lua
index 076742815a..6ed1c10d5c 100644
--- a/indra/newview/scripts/lua/ErrorQueue.lua
+++ b/indra/newview/scripts/lua/ErrorQueue.lua
@@ -3,22 +3,22 @@
 -- raise that error.
 
 local WaitQueue = require('WaitQueue')
--- local debug = require('printf')
-local function debug(...) end
+-- local dbg = require('printf')
+local function dbg(...) end
 
 local ErrorQueue = WaitQueue:new()
 
 function ErrorQueue:Error(message)
     -- Setting Error() is a marker, like closing the queue. Once we reach the
     -- error, every subsequent Dequeue() call will raise the same error.
-    debug('Setting self._closed to %q', message)
+    dbg('Setting self._closed to %q', message)
     self._closed = message
     self:_wake_waiters()
 end
 
 function ErrorQueue:Dequeue()
     local value = WaitQueue.Dequeue(self)
-    debug('ErrorQueue:Dequeue: base Dequeue() got %s', value)
+    dbg('ErrorQueue:Dequeue: base Dequeue() got %s', value)
     if value ~= nil then
         -- queue not yet closed, show caller
         return value
diff --git a/indra/newview/scripts/lua/WaitQueue.lua b/indra/newview/scripts/lua/WaitQueue.lua
index 1fbcc50847..ad4fdecf43 100644
--- a/indra/newview/scripts/lua/WaitQueue.lua
+++ b/indra/newview/scripts/lua/WaitQueue.lua
@@ -5,8 +5,8 @@
 local fiber = require('fiber')
 local Queue = require('Queue')
 
--- local debug = LL.print_debug
-local function debug(...) end
+-- local dbg = require('printf')
+local function dbg(...) end
 
 local WaitQueue = Queue:new()
 
@@ -60,17 +60,18 @@ function WaitQueue:Dequeue()
         -- the queue while there are still items left, and we want the
         -- consumer(s) to retrieve those last few items.
         if self._closed then
-            debug('WaitQueue:Dequeue(): closed')
+            dbg('WaitQueue:Dequeue(): closed')
             return nil
         end
-        debug('WaitQueue:Dequeue(): waiting')
+        dbg('WaitQueue:Dequeue(): waiting')
         -- add the running coroutine to the list of waiters
+        dbg('WaitQueue:Dequeue() running %s', tostring(coroutine.running() or 'main'))
         table.insert(self._waiters, fiber.running())
         -- then let somebody else run
         fiber.wait()
     end
     -- here we're sure this queue isn't empty
-    debug('WaitQueue:Dequeue() calling Queue.Dequeue()')
+    dbg('WaitQueue:Dequeue() calling Queue.Dequeue()')
     return Queue.Dequeue(self)
 end
 
diff --git a/indra/newview/scripts/lua/fiber.lua b/indra/newview/scripts/lua/fiber.lua
index aebf27357f..9057e6c890 100644
--- a/indra/newview/scripts/lua/fiber.lua
+++ b/indra/newview/scripts/lua/fiber.lua
@@ -17,8 +17,8 @@
 -- or with an error).
 
 local printf = require 'printf'
--- local debug = printf
-local function debug(...) end
+-- local dbg = printf
+local function dbg(...) end
 local coro = require 'coro'
 
 local fiber = {}
@@ -78,22 +78,28 @@ function fiber.launch(name, func, ...)
     byname[namekey] = co
     -- and remember it as this fiber's name
     names[co] = namekey
---  debug('launch(%s)', namekey)
---  debug('byname[%s] = %s', namekey, tostring(byname[namekey]))
---  debug('names[%s] = %s', tostring(co), names[co])
---  debug('ready[-1] = %s', tostring(ready[#ready]))
+--  dbg('launch(%s)', namekey)
+--  dbg('byname[%s] = %s', namekey, tostring(byname[namekey]))
+--  dbg('names[%s] = %s', tostring(co), names[co])
+--  dbg('ready[-1] = %s', tostring(ready[#ready]))
 end
 
 -- for debugging
-function fiber.print_all()
-    print('Ready fibers:' .. if next(ready) then '' else ' none')
+function format_all()
+    output = {}
+    table.insert(output, 'Ready fibers:' .. if next(ready) then '' else ' none')
     for _, co in pairs(ready) do
-        printf('  %s: %s', fiber.get_name(co), fiber.status(co))
+        table.insert(output, string.format('  %s: %s', fiber.get_name(co), fiber.status(co)))
     end
-    print('Waiting fibers:' .. if next(waiting) then '' else ' none')
+    table.insert(output, 'Waiting fibers:' .. if next(waiting) then '' else ' none')
     for co in pairs(waiting) do
-        printf('  %s: %s', fiber.get_name(co), fiber.status(co))
+        table.insert(output, string.format('  %s: %s', fiber.get_name(co), fiber.status(co)))
     end
+    return table.concat(output, '\n')
+end
+
+function fiber.print_all()
+    print(format_all())
 end
 
 -- return either the running coroutine or, if called from the main thread,
@@ -160,6 +166,7 @@ end
 
 -- Suspend the current fiber until some other fiber calls fiber.wake() on it
 function fiber.wait()
+    dbg('Fiber %q waiting', fiber.get_name())
     set_waiting()
     -- now yield to other fibers
     fiber.yield()
@@ -175,26 +182,27 @@ function fiber.wake(co)
     waiting[co] = nil
     -- add to end of ready list
     table.insert(ready, co)
+    dbg('Fiber %q ready', fiber.get_name(co))
     -- but don't yet resume it: that happens next time we reach yield()
 end
 
 -- pop and return the next not-dead fiber in the ready list, or nil if none remain
 local function live_ready_iter()
-    -- don't write
+    -- don't write:
     -- for co in table.remove, ready, 1
     -- because it would keep passing a new second parameter!
     for co in function() return table.remove(ready, 1) end do
-        debug('%s live_ready_iter() sees %s, status %s',
+        dbg('%s live_ready_iter() sees %s, status %s',
               fiber.get_name(), fiber.get_name(co), fiber.status(co))
         -- keep removing the head entry until we find one that's not dead,
         -- discarding any dead coroutines along the way
         if co == 'main' or coroutine.status(co) ~= 'dead' then
-            debug('%s live_ready_iter() returning %s',
+            dbg('%s live_ready_iter() returning %s',
                   fiber.get_name(), fiber.get_name(co))
             return co
         end
     end
-    debug('%s live_ready_iter() returning nil', fiber.get_name())
+    dbg('%s live_ready_iter() returning nil', fiber.get_name())
     return nil
 end
 
@@ -214,6 +222,7 @@ end
 -- * false, nil if this is the only remaining fiber
 -- * nil,   x   if configured idle() callback returns non-nil x
 local function scheduler()
+    dbg('scheduler():\n%s', format_all())
     -- scheduler() is asymmetric because Lua distinguishes the main thread
     -- from other coroutines. The main thread can't yield; it can only resume
     -- other coroutines. So although an arbitrary coroutine could resume still
@@ -311,12 +320,12 @@ function fiber.run()
     end
     local others, idle_done
     repeat
-        debug('%s calling fiber.run() calling scheduler()', fiber.get_name())
+        dbg('%s calling fiber.run() calling scheduler()', fiber.get_name())
         others, idle_done = scheduler()
-        debug("%s fiber.run()'s scheduler() returned %s, %s", fiber.get_name(),
+        dbg("%s fiber.run()'s scheduler() returned %s, %s", fiber.get_name(),
               tostring(others), tostring(idle_done))
     until (not others)
-    debug('%s fiber.run() done', fiber.get_name())
+    dbg('%s fiber.run() done', fiber.get_name())
     -- For whatever it's worth, put our own fiber back in the ready list.
     table.insert(ready, fiber.running())
     -- Once there are no more waiting fibers, and the only ready fiber is
diff --git a/indra/newview/scripts/lua/leap.lua b/indra/newview/scripts/lua/leap.lua
index a60819d493..9da1839c68 100644
--- a/indra/newview/scripts/lua/leap.lua
+++ b/indra/newview/scripts/lua/leap.lua
@@ -40,8 +40,8 @@
 
 local fiber = require('fiber')
 local ErrorQueue = require('ErrorQueue')
--- local debug = require('printf')
-local function debug(...) end 
+-- local dbg = require('printf')
+local function dbg(...) end 
 
 local leap = {}
 
@@ -102,7 +102,7 @@ end
 -- 
 -- See also request(), generate().
 function leap.send(pump, data, reqid)
-    debug('leap.send(%s, %s, %s) entry', pump, data, reqid)
+    dbg('leap.send(%s, %s, %s) entry', pump, data, reqid)
     local data = data
     if type(data) == 'table' then
         data = table.clone(data)
@@ -111,7 +111,7 @@ function leap.send(pump, data, reqid)
             data['reqid'] = reqid
         end
     end
-    debug('leap.send(%s, %s) calling post_on()', pump, data)
+    dbg('leap.send(%s, %s) calling post_on()', pump, data)
     LL.post_on(pump, data)
 end
 
@@ -126,7 +126,7 @@ local function requestSetup(pump, data)
     -- WaitForReqid object in leap._pending so dispatch() can find it.
     leap._pending[reqid] = leap.WaitForReqid:new(reqid)
     -- Pass reqid to send() to stamp it into (a copy of) the request data.
-    debug('requestSetup(%s, %s)', pump, data)
+    dbg('requestSetup(%s, %s)', pump, data)
     leap.send(pump, data, reqid)
     return reqid
 end
@@ -152,9 +152,9 @@ end
 function leap.request(pump, data)
     local reqid = requestSetup(pump, data)
     local waitfor = leap._pending[reqid]
-    debug('leap.request(%s, %s) about to wait on %s', pump, data, tostring(waitfor))
+    dbg('leap.request(%s, %s) about to wait on %s', pump, data, tostring(waitfor))
     local ok, response = pcall(waitfor.wait, waitfor)
-    debug('leap.request(%s, %s) got %s: %s', pump, data, ok, response)
+    dbg('leap.request(%s, %s) got %s: %s', pump, data, ok, response)
     -- kill off temporary WaitForReqid object, even if error
     leap._pending[reqid] = nil
     if ok then
@@ -210,7 +210,7 @@ local function unsolicited(pump, data)
     -- we maintain waitfors in descending priority order, so the first waitfor
     -- to claim this event is the one with the highest priority
     for i, waitfor in pairs(leap._waitfors) do
-        debug('unsolicited() checking %s', waitfor.name)
+        dbg('unsolicited() checking %s', waitfor.name)
         if waitfor:handle(pump, data) then
             return
         end
@@ -243,9 +243,9 @@ fiber.set_idle(function ()
         cleanup('done')
         return 'done'
     end
-    debug('leap.idle() calling get_event_next()')
+    dbg('leap.idle() calling get_event_next()')
     local ok, pump, data = pcall(LL.get_event_next)
-    debug('leap.idle() got %s: %s, %s', ok, pump, data)
+    dbg('leap.idle() got %s: %s, %s', ok, pump, data)
     -- ok false means get_event_next() raised a Lua error, pump is message
     if not ok then
         cleanup(pump)
@@ -368,9 +368,9 @@ end
 -- Block the calling coroutine until a suitable unsolicited event (one
 -- for which filter() returns the event) arrives.
 function leap.WaitFor:wait()
-    debug('%s about to wait', self.name)
+    dbg('%s about to wait', self.name)
     local item = self._queue:Dequeue()
-    debug('%s got %s', self.name, item)
+    dbg('%s got %s', self.name, item)
     return item
 end
 
@@ -392,7 +392,7 @@ end
 -- called by unsolicited() for each WaitFor in leap._waitfors
 function leap.WaitFor:handle(pump, data)
     local item = self:filter(pump, data)
-    debug('%s.filter() returned %s', self.name, item)
+    dbg('%s.filter() returned %s', self.name, item)
     -- if this item doesn't pass the filter, we're not interested
     if not item then
         return false