Source Browser ?

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--
16-- We use different targets: "terminal" "logfile", "both" and have no number
17-- channel. Actually, the log channels are now numeric (1,2,3) as with other
18-- symbolics.
19
20local next, type, select, print = next, type, select, print
21local format, gmatch, find = string.format, string.gmatch, string.find
22local concat, insert, remove = table.concat, table.insert, table.remove
23local topattern = string.topattern
24local utfchar = utf.char
25
26local writenl = texio.writeselectornl
27local writelf = texio.writeselectorlf
28local write   = texio.writeselector
29
30local setmetatableindex = table.setmetatableindex
31local formatters        = string.formatters
32local settings_to_hash  = utilities.parsers.settings_to_hash
33local sortedkeys        = table.sortedkeys
34
35-- variant is set now
36
37local variant = "default"
38----- variant = "ansi"
39
40logs       = logs or { }
41local logs = logs
42
43-- we extend the formatters:
44
45formatters.add (
46    formatters, "unichr",
47    [["U+" .. format("%%05X",%s) .. " (" .. utfchar(%s) .. ")"]]
48)
49
50formatters.add (
51    formatters, "chruni",
52    [[utfchar(%s) .. " (U+" .. format("%%05X",%s) .. ")"]]
53)
54
55-- basic loggers
56
57local function ignore() end
58
59setmetatableindex(logs, function(t,k) t[k] = ignore ; return ignore end)
60
61local report, subreport, status, settarget, setformats, settranslations
62
local direct, subdirect, writer, pushtarget, poptarget, setlogfile, settimedlog, setprocessor, setformatters, newline
64
65-- we use formatters but best check for % then because for simple messages but
66-- we don't want this overhead for single messages (not that there are that
67-- many; we could have a special weak table)
68
69local function ansisupported(specification)
70    if specification ~= "ansi" and specification ~= "ansilog" then
71        return false
72    elseif os and os.enableansi then
73        return os.enableansi()
74    else
75        return false
76    end
77end
78
79do
80
81    if arg and ansisupported then
82        -- we're don't have environment.arguments yet
83        for k, v in next, arg do -- k can be negative !
84            if v == "--ansi" or v == "--c:ansi" then
85                if ansisupported("ansi") then
86                    variant = "ansi"
87                end
88                break
89            elseif v == "--ansilog" or v == "--c:ansilog" then
90                if ansisupported("ansilog") then
91                    variant = "ansilog"
92                end
93                break
94            end
95        end
96    end
97
98    local whereto      = "both"
99    local target       = nil
100    local targets      = nil
101
102    local formats      = table.setmetatableindex("self")
103    local translations = table.setmetatableindex("self")
104
    local report_yes, subreport_yes, direct_yes, subdirect_yes, status_yes
106    local report_nop, subreport_nop, direct_nop, subdirect_nop, status_nop
107
108    local variants = {
109        default = {
110            formats = {
111                report_yes    = formatters["%-15s > %s\n"],
112                report_nop    = formatters["%-15s >\n"],
113                direct_yes    = formatters["%-15s > %s"],
114                direct_nop    = formatters["%-15s >"],
115                subreport_yes = formatters["%-15s > %s > %s\n"],
116                subreport_nop = formatters["%-15s > %s >\n"],
117                subdirect_yes = formatters["%-15s > %s > %s"],
118                subdirect_nop = formatters["%-15s > %s >"],
119                status_yes    = formatters["%-15s : %s\n"],
120                status_nop    = formatters["%-15s :\n"],
121            },
122            targets = setmetatableindex( { -- 1, 2, 3,
123                logfile  = 2,
124                log      = 2,
125                file     = 2,
126                console  = 1,
127                terminal = 1,
128                both     = 3,
129            },
130            function(t,k)
131                local v = 3 t[k] = v return v
132            end),
133        },
134        ansi = {
135            formats = {
136                report_yes    = formatters["%-15s > %s\n"],
137                report_nop    = formatters["%-15s >\n"],
138                direct_yes    = formatters["%-15s > %s"],
139                direct_nop    = formatters["%-15s >"],
140                subreport_yes = formatters["%-15s > %s > %s\n"],
141                subreport_nop = formatters["%-15s > %s >\n"],
142                subdirect_yes = formatters["%-15s > %s > %s"],
143                subdirect_nop = formatters["%-15s > %s >"],
144                status_yes    = formatters["%-15s : %s\n"],
145                status_nop    = formatters["%-15s :\n"],
146            },
147            targets = setmetatableindex( { 1, 1, 1,
148                logfile  = false,
149                log      = false,
150                file     = false,
151                console  = 1,
152                terminal = 1,
153                both     = 1,
154            }, function(t,k) local v = 1 t[k] = v return v end),
155        }
156    }
157
158    variants.ansilog = {
159        formats = variants.ansi.formats,
160        targets = variants.default.targets,
161    }
162
163-- do
164--     local iosize   = 512
165--     local iomode   = "line"
166--     local ioflush  = io.flush
167--     local iooutput = io.output
168--     iooutput():setvbuf(iomode,iosize)
169--     io.flush = function()
170--     --         ioflush()
171--     --         iooutput():setvbuf(iomode,iosize)
172--     end
173-- end
174
175    logs.flush = io.flush
176
177    writer = function(...)
178        if target then
179            writenl(target,...)
180        end
181    end
182
183    newline = function()
        if target then
185            writelf(target)
         -- writenl(target,"")
187        end
    end
189
190    report = function(a,b,c,...)
191        if not target then
192            -- ignore
193        elseif c ~= nil then
194            writenl(target,report_yes(translations[a],formatters[formats[b]](c,...)))
195        elseif b then
196            writenl(target,report_yes(translations[a],formats[b]))
197        elseif a then
            writenl(target,report_nop(translations[a]))
199        else
            writenl(target)
201        end
    end
203
204    direct = function(a,b,c,...)
205        if not target then
206            return ""
207        elseif c ~= nil then
208            return direct_yes(translations[a],formatters[formats[b]](c,...))
209        elseif b then
210            return direct_yes(translations[a],formats[b])
211        elseif a then
            return direct_nop(translations[a])
213        else
            return ""
215        end
    end
217
218    subreport = function(a,s,b,c,...)
219        if not target then
220            -- ignore
221        elseif c ~= nil then
222            writenl(target,subreport_yes(translations[a],translations[s],formatters[formats[b]](c,...)))
223        elseif b then
224            writenl(target,subreport_yes(translations[a],translations[s],formats[b]))
225        elseif a then
            writenl(target,subreport_nop(translations[a],translations[s]))
227        else
            writenl(target)
229        end
    end
231
232    subdirect = function(a,s,b,c,...)
233        if not target then
234            return ""
235        elseif c ~= nil then
236            return subdirect_yes(translations[a],translations[s],formatters[formats[b]](c,...))
237        elseif b then
238            return subdirect_yes(translations[a],translations[s],formats[b])
239        elseif a then
            return subdirect_nop(translations[a],translations[s])
241        else
            return ""
243        end
    end
245
246    status = function(a,b,c,...)
247        if not target then
248            -- ignore
249        elseif c ~= nil then
250            writenl(target,status_yes(translations[a],formatters[formats[b]](c,...)))
251        elseif b then
252            writenl(target,status_yes(translations[a],formats[b]))
253        elseif a then
254            writenl(target,status_nop(translations[a]))
255        else
256            writenl(target)
257        end
258    end
259
260    settarget = function(askedwhereto)
261        whereto = askedwhereto or whereto or "both"
262        target = targets[whereto]
263        if not target then
264            whereto = "both"
265            target  = targets[whereto]
266        end
267        if target == targets.both or target == targets.terminal then
268            logs.flush = io.flush
269        else
270            logs.flush = ignore
271        end
272    end
273
274    local stack = { }
275
276    pushtarget = function(newtarget)
277        insert(stack,target)
278        settarget(newtarget)
279    end
280
    poptarget = function()
        if #stack > 0 then
283            settarget(remove(stack))
284        end
285    end
286
287    setformats = function(f)
288        formats = f
289    end
290
291    settranslations = function(t)
292        translations = t
293    end
294
295    setprocessor = function(f)
296        local writeline = writenl
297        writenl = function(target,...)
298            if target then
299                writeline(target,f(...))
300            end
301        end
302    end
303
304    setformatters = function(specification)
305        local t = nil
306        local f = nil
307        local d = variants.default
308        if not specification then
309            --
310        elseif type(specification) == "table" then
311            t = specification.targets
312            f = specification.formats or specification
313        else
314            if not ansisupported(specification) then
315                specification = "default"
316            end
317            local v = variants[specification]
318            if v then
319                t = v.targets
320                f = v.formats
321                variant = specification
322            end
323        end
324        targets = t or d.targets
325        target = targets[whereto]
326        if f then
327            d = d.formats
328        else
329            f = d.formats
330            d = f
331        end
332        setmetatableindex(f,d)
333        report_yes    = f.report_yes
334        report_nop    = f.report_nop
335        subreport_yes = f.subreport_yes
336        subreport_nop = f.subreport_nop
337        direct_yes    = f.direct_yes
338        direct_nop    = f.direct_nop
339        subdirect_yes = f.subdirect_yes
340        subdirect_nop = f.subdirect_nop
341        status_yes    = f.status_yes
342        status_nop    = f.status_nop
343        settarget(whereto)
344    end
345
346    setformatters(variant)
347
348    setlogfile  = ignore
349    settimedlog = ignore

351end
352
353-- io.output():setvbuf("line",1024)
354
355logs.report          = report
356logs.subreport       = subreport
357logs.status          = status
358logs.settarget       = settarget
359logs.pushtarget      = pushtarget
360logs.poptarget       = poptarget
361logs.setformats      = setformats
362logs.settranslations = settranslations
363
364logs.setlogfile      = setlogfile
365logs.settimedlog     = settimedlog
366logs.setprocessor    = setprocessor
367logs.setformatters   = setformatters
368
369logs.direct          = direct
370logs.subdirect       = subdirect
371logs.writer          = writer
372logs.newline         = newline
373
374local data   = { }
375local states = nil
376local force  = false
377
378function logs.reporter(category,subcategory)
379    local logger = data[category]
380    if not logger then
381        local state = states == true
382        if not state and type(states) == "table" then
383            for c, _ in next, states do
384                if find(category,c) then
385                    state = true
386                    break
387                end
388            end
389        end
390        logger = {
391            reporters = { },
392            state     = state,
393        }
394        data[category] = logger
395    end
396    local reporter = logger.reporters[subcategory or "default"]
397    if not reporter then
398        if subcategory then
399            reporter = function(...)
400                if force or not logger.state then
401                    subreport(category,subcategory,...)
402                end
403            end
404            logger.reporters[subcategory] = reporter
405        else
406            local tag = category
407            reporter = function(...)
408                if force or not logger.state then
409                    report(category,...)
410                end
411            end
412            logger.reporters.default = reporter
413        end
414    end
415    return reporter
416end
417
418logs.new = logs.reporter -- for old times sake
419
420-- context specicific: this ends up in the macro stream
421
422local ctxreport = logs.writer
423
424function logs.setmessenger(m)
425    ctxreport = m
426end
427
428function logs.messenger(category,subcategory)
429    -- we need to avoid catcode mess (todo: fast context)
430    if subcategory then
431        return function(...)
432            ctxreport(subdirect(category,subcategory,...))
433        end
434    else
435        return function(...)
436            ctxreport(direct(category,...))
437        end
438    end
439end
440
441-- so far
442
443local function setblocked(category,value) -- v.state == value == true : disable
444    if category == true or category == "all" then
445        -- lock all
446        category, value = "*", true
447    elseif category == false then
448        -- unlock all
449        category, value = "*", false
450    elseif value == nil then
451        -- lock selective
452        value = true
453    end
454    if category == "*" then
455        states = value
456        for k, v in next, data do
457            v.state = value
458        end
459    else
460        alllocked = false
461        states = settings_to_hash(category,type(states)=="table" and states or nil)
462        for c in next, states do
463            local v = data[c]
464            if v then
465                v.state = value
466            else
467                c = topattern(c,true,true)
468                for k, v in next, data do
469                    if find(k,c) then
470                        v.state = value
471                    end
472                end
473            end
474        end
475    end
476end
477
478function logs.disable(category,value)
479    setblocked(category,value == nil and true or value)
480end
481
482function logs.enable(category)
483    setblocked(category,false)
484end
485
486function logs.categories()
487    return sortedkeys(data)
488end
489
490function logs.show()
491    local n, c, s, max = 0, 0, 0, 0
492    for category, v in table.sortedpairs(data) do
493        n = n + 1
494        local state = v.state
495        local reporters = v.reporters
496        local nc = #category
497        if nc > c then
498            c = nc
499        end
500        for subcategory, _ in next, reporters do
501            local ns = #subcategory
502            if ns > c then
503                s = ns
504            end
505            local m = nc + ns
506            if m > max then
507                max = m
508            end
509        end
510        local subcategories = concat(sortedkeys(reporters),", ")
511        if state == true then
512            state = "disabled"
513        elseif state == false then
514            state = "enabled"
515        else
516            state = "unknown"
517        end
518        -- no new here
519        report("logging","category %a, subcategories %a, state %a",category,subcategories,state)
520    end
521    report("logging","categories: %s, max category: %s, max subcategory: %s, max combined: %s",n,c,s,max)
522end
523
524local delayed_reporters = { }
525
526setmetatableindex(delayed_reporters,function(t,k)
527    local v = logs.reporter(k.name)
528    t[k] = v
529    return v
530end)
531
532function utilities.setters.report(setter,...)
533    delayed_reporters[setter](...)
534end
535
536directives.register("logs.blocked", function(v)
537    setblocked(v,true)
538end)
539
540directives.register("logs.target", function(v)
541    settarget(v)
542end)
543
544do
545
546    local report      = logs.reporter("pages") -- not needed but saves checking when we grep for it
547    local texgetcount = tex and tex.getcount
548
549    local real, user, sub = 0, 0, 0
550
551    function logs.start_page_number()
552        real = texgetcount("realpageno")
553        user = texgetcount("userpageno")
554        sub  = texgetcount("subpageno")
555    end
556
557    local timing   = false
558    local usage    = false
559    local lasttime = nil
560
561    logs.private = {
562        enablepagetiming = function()
563            usage = true
564        end,
565        getpagetiming = function()
566            return type(usage) == "table" and usage
567        end,
568    }
569
570    trackers.register("pages.timing", function() timing = "" end)
571
572    function logs.stop_page_number() -- the first page can includes the initialization so we omit this in average
573        if timing or usage then
574            local elapsed = statistics.currenttime(statistics)
575            local average, page
576            if not lasttime or real < 2 then
577                average = elapsed
578                page    = elapsed
579            else
580                average = elapsed / (real - 1)
581                page    = elapsed - lasttime
582            end
583            lasttime = elapsed
584            if timing then
585                timing = formatters[", total %0.03f, page %0.03f, average %0.03f"](elapsed,page,average)
586            end
587            if usage then
588                usage = {
589                    page = {
590                        real = real,
591                        user = user,
592                        sub  = sub,
593                    },
594                    time = {
595                        elapsed = elapsed,
596                        page    = page,
597                        average = average,
598                    }
599                }
600            end
601        end
602        if real <= 0 then
603            report("flushing page%s",timing)
604        elseif user <= 0 then
605            report("flushing realpage %s%s",real,timing)
606        elseif sub <= 0 then
607            report("flushing realpage %s, userpage %s%s",real,user,timing)
608        else
609            report("flushing realpage %s, userpage %s, subpage %s%s",real,user,sub,timing)
610        end
611        logs.flush()
612    end
613
614end
615
616-- we don't have show_open and show_close callbacks yet
617
618do
619
620    local texerror = tex and tex.error or print
621
622    function logs.texerrormessage(fmt,first,...) -- for the moment we put this function here
623        texerror(first and formatters[fmt](first,...) or fmt)
624    end
625
626end
627
628-- this is somewhat slower but prevents out-of-order messages when print is mixed
629-- with texio.write
630
631-- io.stdout:setvbuf('no')
632-- io.stderr:setvbuf('no')
633
634-- windows: > nul  2>&1
635-- unix   : > null 2>&1
636
637if package.helpers.report then
638    package.helpers.report = logs.reporter("package loader") -- when used outside mtxrun
639end
640
641-- logs.errors=missing references,missing characters
642-- logs.errors=characters
643-- logs.errors=missing
644-- logs.errors=*
645-- logs.quitonerror=missing modules
646
647do
648
649    local finalactions  = { }
650    local fatalerrors   = { }
651    local possiblefatal = { }
652    local quitonerror   = { }
653    local loggingerrors = false
654
655    function logs.loggingerrors()
656        return loggingerrors
657    end
658
659    local function register(v)
660        loggingerrors = v
661        if type(v) == "string" then
662            local target = settings_to_hash(v)
663            for k, v in next, target do
664                target[k] = string.topattern(k)
665            end
666            return target
667        else
668            return { }
669        end
670    end
671
672    directives.register("logs.errors",     function(v) fatalerrors = register(v) end)
673    directives.register("logs.quitonerror",function(v) quitonerror = register(v) end)
674
675    function logs.registerfinalactions(...)
676        insert(finalactions,...) -- so we can force an order if needed
677    end
678
679    local what   = nil
680    local report = nil
681    local state  = nil
682    local target = nil
683    local fatal  = false
684
685    local function startlogging(t,r,w,s)
686        target = t
687        state  = force
688        force  = true
689        report = type(r) == "function" and r or logs.reporter(r)
690        what   = w
691        pushtarget(target)
692        newline()
693        if s then
694            report("start %s: %s",what,s)
695        else
696            report("start %s",what or "")
697        end
698        if target == "logfile" then
699            newline()
700        end
701        return report
702    end
703
704    local function stoplogging()
705        if target == "logfile" then
706            newline()
707        end
708        report("stop %s",what or "")
709        if target == "logfile" then
710            newline()
711        end
712        poptarget()
713        state = oldstate
714        if fatal then
715            logs.report("error logging","error marked as fatal")
716            luatex.abort()
717        end
718    end
719
720    function logs.startfilelogging(...)
721        return startlogging("logfile", ...)
722    end
723
724    logs.stopfilelogging = stoplogging
725
726    local done = false
727
728    function logs.starterrorlogging(r,w,...)
729        if not done then
730            pushtarget("terminal")
731            newline()
732            logs.report("error logging","start possible issues")
733            poptarget()
734            done = true
735        end
736        if fatalerrors[w] then
737            possiblefatal[w] = true
738        else
739            for k, v in next, quitonerror do
740                if find(w,v) then
741                    fatal = true
742                end
743            end
744            for k, v in next, fatalerrors do
745                if find(w,v) then
746                    possiblefatal[w] = true
747                    break
748                end
749            end
750        end
751        return startlogging("terminal",r,w,...)
752    end
753
754    logs.stoperrorlogging = stoplogging
755
756    function logs.finalactions()
757        if #finalactions > 0 then
758            for i=1,#finalactions do
759                finalactions[i]()
760            end
761            if done then
762                pushtarget("terminal")
763                newline()
764                logs.report("error logging","stop possible issues")
765                poptarget()
766            end
767            return next(possiblefatal) and sortedkeys(possiblefatal) or false
768        end
769    end
770
771end
772
773-- just in case we load from context
774
775local dummy = function() end
776
777function logs.application(t)
778    return {
779        name     = t.name or tex.jobname,
780        banner   = t.banner,
781        report   = logs.reporter(t.name),
782        moreinfo = dummy,
783        export   = dummy,
784        help     = dummy,
785        identify = dummy,
786        version  = dummy,
787    }
788end
789
790-- for old times sake
791
792do
793
794    local datetime = os.date
795    local sleep = os.sleep
796    local openfile = io.open
797
798    local f_syslog = formatters["%s %s => %s => %s => %s\r"]
799
800    function logs.system(whereto,process,jobname,category,fmt,arg,...)
801        local message = f_syslog(datetime("%d/%m/%y %H:%m:%S"),process,jobname,category,arg == nil and fmt or format(fmt,arg,...))
802        for i=1,10 do
803            local f = openfile(whereto,"a") -- we can consider keeping the file open
804            if f then
805                f:write(message)
806                f:close()
807                break
808            else
809                sleep(0.1)
810            end
811        end
812    end
813
814end
815