luat-log.lua /size: 22 Kb    last modification: 2021-10-28 13:50
1if not modules then modules = { } end modules ['luat-log'] = {
2    version   = 1.001,
3    comment   = "companion to trac-log.mkiv",
4    author    = "Hans Hagen, PRAGMA-ADE, Hasselt NL",
5    copyright = "PRAGMA ADE / ConTeXt Development Team",
6    license   = "see context related readme files"
7}
8
9-- In fact all writes could go through lua and we could write the console and
10-- terminal handler in lua then. Ok, maybe it's slower then, so a no-go.
11
12-- This used to be combined in trac-log but as we also split between mkiv and lmtx
13-- we now have dedicated files. A side effect is a smaller format and a smaller
14-- mtxrun.
15
16local next, type, select, print = next, type, select, print
17local format, gmatch, find = string.format, string.gmatch, string.find
18local concat, insert, remove = table.concat, table.insert, table.remove
19local topattern = string.topattern
20local utfchar = utf.char
21local datetime = os.date
22local openfile = io.open
23
24local write_nl = texio and texio.write_nl
25local write    = texio and texio.write
26
27local setmetatableindex = table.setmetatableindex
28local formatters        = string.formatters
29local settings_to_hash  = utilities.parsers.settings_to_hash
30local sortedkeys        = table.sortedkeys
31
32-- variant is set now
33
34local variant = "default"
35----- variant = "ansi"
36
37logs       = logs or { }
38local logs = logs
39
40-- we extend the formatters:
41
42formatters.add (
43    formatters, "unichr",
44    [["U+" .. format("%%05X",%s) .. " (" .. utfchar(%s) .. ")"]]
45)
46
47formatters.add (
48    formatters, "chruni",
49    [[utfchar(%s) .. " (U+" .. format("%%05X",%s) .. ")"]]
50)
51
52-- basic loggers
53
54local function ignore() end
55
56setmetatableindex(logs, function(t,k) t[k] = ignore ; return ignore end)
57
58local report, subreport, status, settarget, setformats, settranslations
59
60local direct, subdirect, writer, pushtarget, poptarget, setlogfile, settimedlog, setprocessor, setformatters, newline
61
62-- we use formatters but best check for % then because for simple messages but
63-- we don't want this overhead for single messages (not that there are that
64-- many; we could have a special weak table)
65
66local function ansisupported(specification)
67    if specification ~= "ansi" and specification ~= "ansilog" then
68        return false
69    elseif os and os.enableansi then
70        return os.enableansi()
71    else
72        return false
73    end
74end
75
76do
77
78    if texio.setescape then
79        texio.setescape(0) -- or (false)
80    end
81
82    if arg and ansisupported then
83        -- we're don't have environment.arguments yet
84        for k, v in next, arg do -- k can be negative !
85            if v == "--ansi" or v == "--c:ansi" then
86                if ansisupported("ansi") then
87                    variant = "ansi"
88                end
89                break
90            elseif v == "--ansilog" or v == "--c:ansilog" then
91                if ansisupported("ansilog") then
92                    variant = "ansilog"
93                end
94                break
95            end
96        end
97    end
98
99    local function useluawrites()
100
101        -- quick hack, awaiting speedup in engine (8 -> 6.4 sec for --make with console2)
102        -- still needed for luajittex .. luatex should not have that ^^ mess
103
104        local texio_write_nl = texio.write_nl
105        local texio_write    = texio.write
106        local io_write       = io.write
107
108        write_nl = function(target,...)
109            if not io_write then
110                io_write = io.write
111            end
112            if target == "term and log" then
113                texio_write_nl("log",...)
114                texio_write_nl("term","")
115                io_write(...)
116            elseif target == "log" then
117                texio_write_nl("log",...)
118            elseif target == "term" then
119                texio_write_nl("term","")
120                io_write(...)
121            elseif type(target) == "number" then
122                texio_write_nl(target,...) -- a tex output channel
123            elseif target ~= "none" then
124                texio_write_nl("log",target,...)
125                texio_write_nl("term","")
126                io_write(target,...)
127            end
128        end
129
130        write = function(target,...)
131            if not io_write then
132                io_write = io.write
133            end
134            if target == "term and log" then
135                texio_write("log",...)
136                io_write(...)
137            elseif target == "log" then
138                texio_write("log",...)
139            elseif target == "term" then
140                io_write(...)
141            elseif type(target) == "number" then
142                texio_write(target,...) -- a tex output channel
143            elseif target ~= "none" then
144                texio_write("log",target,...)
145                io_write(target,...)
146            end
147        end
148
149        texio.write    = write
150        texio.write_nl = write_nl
151
152        useluawrites   = ignore
153
154    end
155
156 -- local format = string.formatter
157
158    local whereto      = "both"
159    local target       = nil
160    local targets      = nil
161
162    local formats      = table.setmetatableindex("self")
163    local translations = table.setmetatableindex("self")
164
165    local report_yes, subreport_yes, direct_yes, subdirect_yes, status_yes
166    local report_nop, subreport_nop, direct_nop, subdirect_nop, status_nop
167
168    local variants = {
169        default = {
170            formats = {
171                report_yes    = formatters["%-15s > %s\n"],
172                report_nop    = formatters["%-15s >\n"],
173                direct_yes    = formatters["%-15s > %s"],
174                direct_nop    = formatters["%-15s >"],
175                subreport_yes = formatters["%-15s > %s > %s\n"],
176                subreport_nop = formatters["%-15s > %s >\n"],
177                subdirect_yes = formatters["%-15s > %s > %s"],
178                subdirect_nop = formatters["%-15s > %s >"],
179                status_yes    = formatters["%-15s : %s\n"],
180                status_nop    = formatters["%-15s :\n"],
181            },
182            targets = {
183                logfile  = "log",
184                log      = "log",
185                file     = "log",
186                console  = "term",
187                terminal = "term",
188                both     = "term and log",
189            },
190        },
191        ansi = {
192            formats = {
193                report_yes    = formatters["%-15s > %s\n"],
194                report_nop    = formatters["%-15s >\n"],
195                direct_yes    = formatters["%-15s > %s"],
196                direct_nop    = formatters["%-15s >"],
197                subreport_yes = formatters["%-15s > %s > %s\n"],
198                subreport_nop = formatters["%-15s > %s >\n"],
199                subdirect_yes = formatters["%-15s > %s > %s"],
200                subdirect_nop = formatters["%-15s > %s >"],
201                status_yes    = formatters["%-15s : %s\n"],
202                status_nop    = formatters["%-15s :\n"],
203            },
204            targets = {
205                logfile  = "none",
206                log      = "none",
207                file     = "none",
208                console  = "term",
209                terminal = "term",
210                both     = "term",
211            },
212        }
213    }
214
215    variants.ansilog = {
216        formats = variants.ansi.formats,
217        targets = variants.default.targets,
218    }
219
220    logs.flush = io.flush
221
222    writer = function(...)
223        write_nl(target,...)
224    end
225
226    newline = function()
227        write_nl(target,"\n")
228    end
229
230    report = function(a,b,c,...)
231        if c ~= nil then
232            write_nl(target,report_yes(translations[a],formatters[formats[b]](c,...)))
233        elseif b then
234            write_nl(target,report_yes(translations[a],formats[b]))
235        elseif a then
236            write_nl(target,report_nop(translations[a]))
237        else
238            write_nl(target,"\n")
239        end
240    end
241
242    direct = function(a,b,c,...)
243        if c ~= nil then
244            return direct_yes(translations[a],formatters[formats[b]](c,...))
245        elseif b then
246            return direct_yes(translations[a],formats[b])
247        elseif a then
248            return direct_nop(translations[a])
249        else
250            return ""
251        end
252    end
253
254    subreport = function(a,s,b,c,...)
255        if c ~= nil then
256            write_nl(target,subreport_yes(translations[a],translations[s],formatters[formats[b]](c,...)))
257        elseif b then
258            write_nl(target,subreport_yes(translations[a],translations[s],formats[b]))
259        elseif a then
260            write_nl(target,subreport_nop(translations[a],translations[s]))
261        else
262            write_nl(target,"\n")
263        end
264    end
265
266    subdirect = function(a,s,b,c,...)
267        if c ~= nil then
268            return subdirect_yes(translations[a],translations[s],formatters[formats[b]](c,...))
269        elseif b then
270            return subdirect_yes(translations[a],translations[s],formats[b])
271        elseif a then
272            return subdirect_nop(translations[a],translations[s])
273        else
274            return ""
275        end
276    end
277
278    status = function(a,b,c,...)
279        if c ~= nil then
280            write_nl(target,status_yes(translations[a],formatters[formats[b]](c,...)))
281        elseif b then
282            write_nl(target,status_yes(translations[a],formats[b]))
283        elseif a then
284            write_nl(target,status_nop(translations[a]))
285        else
286            write_nl(target,"\n")
287        end
288    end
289
290    settarget = function(askedwhereto)
291        whereto = askedwhereto or whereto or "both"
292        target = targets[whereto]
293        if not target then
294            whereto   = "both"
295            target = targets[whereto]
296        end
297        if target == "term" or target == "term and log" then
298            logs.flush = io.flush
299        else
300            logs.flush = ignore
301        end
302    end
303
304    local stack = { }
305
306    pushtarget = function(newtarget)
307        insert(stack,target)
308        settarget(newtarget)
309    end
310
311    poptarget = function()
312        if #stack > 0 then
313            settarget(remove(stack))
314        end
315    end
316
317    setformats = function(f)
318        formats = f
319    end
320
321    settranslations = function(t)
322        translations = t
323    end
324
325    setprocessor = function(f)
326        local writeline = write_nl
327        write_nl = function(target,...)
328            writeline(target,f(...))
329        end
330    end
331
332    setformatters = function(specification)
333        local t = nil
334        local f = nil
335        local d = variants.default
336        if not specification then
337            --
338        elseif type(specification) == "table" then
339            t = specification.targets
340            f = specification.formats or specification
341        else
342            if not ansisupported(specification) then
343                specification = "default"
344            end
345            local v = variants[specification]
346            if v then
347                t = v.targets
348                f = v.formats
349                variant = specification
350            end
351        end
352        targets = t or d.targets
353        target = targets[whereto] or target
354        if f then
355            d = d.formats
356        else
357            f = d.formats
358            d = f
359        end
360        setmetatableindex(f,d)
361        report_yes    = f.report_yes
362        report_nop    = f.report_nop
363        subreport_yes = f.subreport_yes
364        subreport_nop = f.subreport_nop
365        direct_yes    = f.direct_yes
366        direct_nop    = f.direct_nop
367        subdirect_yes = f.subdirect_yes
368        subdirect_nop = f.subdirect_nop
369        status_yes    = f.status_yes
370        status_nop    = f.status_nop
371        if variant == "ansi" or variant == "ansilog" then
372            useluawrites() -- because tex escapes ^^, not needed in lmtx
373        end
374        settarget(whereto)
375    end
376
377    setformatters(variant)
378
379    setlogfile  = ignore
380    settimedlog = ignore
381
382 -- settimedlog = function()
383 --     local localtime = os.localtime
384 --     local writeline = write_nl
385 --     write_nl = function(f,...)
386 --         writeline(f,localtime() .. " | " .. concat { ... })
387 --     end
388 --     settimedlog = ignore
389 -- end
390
391end
392
393logs.report          = report
394logs.subreport       = subreport
395logs.status          = status
396logs.settarget       = settarget
397logs.pushtarget      = pushtarget
398logs.poptarget       = poptarget
399logs.setformats      = setformats
400logs.settranslations = settranslations
401
402logs.setlogfile      = setlogfile
403logs.settimedlog     = settimedlog
404logs.setprocessor    = setprocessor
405logs.setformatters   = setformatters
406
407logs.direct          = direct
408logs.subdirect       = subdirect
409logs.writer          = writer
410logs.newline         = newline
411
412local data   = { }
413local states = nil
414local force  = false
415
416function logs.reporter(category,subcategory)
417    local logger = data[category]
418    if not logger then
419        local state = states == true
420        if not state and type(states) == "table" then
421            for c, _ in next, states do
422                if find(category,c) then
423                    state = true
424                    break
425                end
426            end
427        end
428        logger = {
429            reporters = { },
430            state     = state,
431        }
432        data[category] = logger
433    end
434    local reporter = logger.reporters[subcategory or "default"]
435    if not reporter then
436        if subcategory then
437            reporter = function(...)
438                if force or not logger.state then
439                    subreport(category,subcategory,...)
440                end
441            end
442            logger.reporters[subcategory] = reporter
443        else
444            local tag = category
445            reporter = function(...)
446                if force or not logger.state then
447                    report(category,...)
448                end
449            end
450            logger.reporters.default = reporter
451        end
452    end
453    return reporter
454end
455
456logs.new = logs.reporter -- for old times sake
457
458-- context specicific: this ends up in the macro stream
459
460local ctxreport = logs.writer
461
462function logs.setmessenger(m)
463    ctxreport = m
464end
465
466function logs.messenger(category,subcategory)
467    -- we need to avoid catcode mess (todo: fast context)
468    if subcategory then
469        return function(...)
470            ctxreport(subdirect(category,subcategory,...))
471        end
472    else
473        return function(...)
474            ctxreport(direct(category,...))
475        end
476    end
477end
478
479-- so far
480
481local function setblocked(category,value) -- v.state == value == true : disable
482    if category == true or category == "all" then
483        -- lock all
484        category, value = "*", true
485    elseif category == false then
486        -- unlock all
487        category, value = "*", false
488    elseif value == nil then
489        -- lock selective
490        value = true
491    end
492    if category == "*" then
493        states = value
494        for k, v in next, data do
495            v.state = value
496        end
497    else
498        alllocked = false
499        states = settings_to_hash(category,type(states)=="table" and states or nil)
500        for c in next, states do
501            local v = data[c]
502            if v then
503                v.state = value
504            else
505                c = topattern(c,true,true)
506                for k, v in next, data do
507                    if find(k,c) then
508                        v.state = value
509                    end
510                end
511            end
512        end
513    end
514end
515
516function logs.disable(category,value)
517    setblocked(category,value == nil and true or value)
518end
519
520function logs.enable(category)
521    setblocked(category,false)
522end
523
524function logs.categories()
525    return sortedkeys(data)
526end
527
528function logs.show()
529    local n, c, s, max = 0, 0, 0, 0
530    for category, v in table.sortedpairs(data) do
531        n = n + 1
532        local state = v.state
533        local reporters = v.reporters
534        local nc = #category
535        if nc > c then
536            c = nc
537        end
538        for subcategory, _ in next, reporters do
539            local ns = #subcategory
540            if ns > c then
541                s = ns
542            end
543            local m = nc + ns
544            if m > max then
545                max = m
546            end
547        end
548        local subcategories = concat(sortedkeys(reporters),", ")
549        if state == true then
550            state = "disabled"
551        elseif state == false then
552            state = "enabled"
553        else
554            state = "unknown"
555        end
556        -- no new here
557        report("logging","category %a, subcategories %a, state %a",category,subcategories,state)
558    end
559    report("logging","categories: %s, max category: %s, max subcategory: %s, max combined: %s",n,c,s,max)
560end
561
562local delayed_reporters = { }
563
564setmetatableindex(delayed_reporters,function(t,k)
565    local v = logs.reporter(k.name)
566    t[k] = v
567    return v
568end)
569
570function utilities.setters.report(setter,...)
571    delayed_reporters[setter](...)
572end
573
574directives.register("logs.blocked", function(v)
575    setblocked(v,true)
576end)
577
578directives.register("logs.target", function(v)
579    settarget(v)
580end)
581
582do
583
584    local report      = logs.reporter("pages") -- not needed but saves checking when we grep for it
585    local texgetcount = tex and tex.getcount
586
587    local real, user, sub = 0, 0, 0
588
589    function logs.start_page_number()
590        real = texgetcount("realpageno")
591        user = texgetcount("userpageno")
592        sub  = texgetcount("subpageno")
593    end
594
595    local timing   = false
596    local usage    = false
597    local lasttime = nil
598
599    logs.private = {
600        enablepagetiming = function()
601            usage = true
602        end,
603        getpagetiming = function()
604            return type(usage) == "table" and usage
605        end,
606    }
607
608    trackers.register("pages.timing", function() timing = "" end)
609
610    function logs.stop_page_number() -- the first page can includes the initialization so we omit this in average
611        if timing or usage then
612            local elapsed = statistics.currenttime(statistics)
613            local average, page
614            if not lasttime or real < 2 then
615                average = elapsed
616                page    = elapsed
617            else
618                average = elapsed / (real - 1)
619                page    = elapsed - lasttime
620            end
621            lasttime = elapsed
622            if timing then
623                timing = formatters[", total %0.03f, page %0.03f, average %0.03f"](elapsed,page,average)
624            end
625            if usage then
626                usage = {
627                    page = {
628                        real = real,
629                        user = user,
630                        sub  = sub,
631                    },
632                    time = {
633                        elapsed = elapsed,
634                        page    = page,
635                        average = average,
636                    }
637                }
638            end
639        end
640        if real <= 0 then
641            report("flushing page%s",timing)
642        elseif user <= 0 then
643            report("flushing realpage %s%s",real,timing)
644        elseif sub <= 0 then
645            report("flushing realpage %s, userpage %s%s",real,user,timing)
646        else
647            report("flushing realpage %s, userpage %s, subpage %s%s",real,user,sub,timing)
648        end
649        logs.flush()
650    end
651
652end
653
654-- we don't have show_open and show_close callbacks yet
655
656do
657    local texerror   = tex and tex.error or print
658    local formatters = string.formatters
659
660    function logs.texerrormessage(fmt,first,...) -- for the moment we put this function here
661        texerror(first and formatters[fmt](first,...) or fmt)
662    end
663
664end
665
666-- this is somewhat slower but prevents out-of-order messages when print is mixed
667-- with texio.write
668
669-- io.stdout:setvbuf('no')
670-- io.stderr:setvbuf('no')
671
672-- windows: > nul  2>&1
673-- unix   : > null 2>&1
674
675if package.helpers.report then
676    package.helpers.report = logs.reporter("package loader") -- when used outside mtxrun
677end
678
679do
680
681    local finalactions  = { }
682    local fatalerrors   = { }
683    local possiblefatal = { }
684    local loggingerrors = false
685
686    function logs.loggingerrors()
687        return loggingerrors
688    end
689
690    directives.register("logs.errors",function(v)
691        loggingerrors = v
692        if type(v) == "string" then
693            fatalerrors = settings_to_hash(v)
694        else
695            fatalerrors = { }
696        end
697    end)
698
699    function logs.registerfinalactions(...)
700        insert(finalactions,...) -- so we can force an order if needed
701    end
702
703    local what   = nil
704    local report = nil
705    local state  = nil
706    local target = nil
707
708    local function startlogging(t,r,w,s)
709        target = t
710        state  = force
711        force  = true
712        report = type(r) == "function" and r or logs.reporter(r)
713        what   = w
714        pushtarget(target)
715        newline()
716        if s then
717            report("start %s: %s",what,s)
718        else
719            report("start %s",what or "")
720        end
721        if target == "logfile" then
722            newline()
723        end
724        return report
725    end
726
727    local function stoplogging()
728        if target == "logfile" then
729            newline()
730        end
731        report("stop %s",what or "")
732        if target == "logfile" then
733            newline()
734        end
735        poptarget()
736        state = oldstate
737    end
738
739    function logs.startfilelogging(...)
740        return startlogging("logfile", ...)
741    end
742
743    logs.stopfilelogging = stoplogging
744
745    local done = false
746
747    function logs.starterrorlogging(r,w,...)
748        if not done then
749            pushtarget("terminal")
750            newline()
751            logs.report("error logging","start possible issues")
752            poptarget()
753            done = true
754        end
755        if fatalerrors[w] then
756            possiblefatal[w] = true
757        end
758        return startlogging("terminal",r,w,...)
759    end
760
761    logs.stoperrorlogging = stoplogging
762
763    function logs.finalactions()
764        if #finalactions > 0 then
765            for i=1,#finalactions do
766                finalactions[i]()
767            end
768            if done then
769                pushtarget("terminal")
770                newline()
771                logs.report("error logging","stop possible issues")
772                poptarget()
773            end
774            return next(possiblefatal) and sortedkeys(possiblefatal) or false
775        end
776    end
777
778end
779
780-- just in case we load from context
781
782local dummy = function() end
783
784function logs.application(t)
785    return {
786        name     = t.name or tex.jobname,
787        banner   = t.banner,
788        report   = logs.reporter(t.name),
789        moreinfo = dummy,
790        export   = dummy,
791        help     = dummy,
792        identify = dummy,
793        version  = dummy,
794    }
795end
796