key "FMT_%Y-%m-%d %H:%M:%S" not known in dictionary

[bovine]

We are occasionally seeing the following traceback error on a production system utilizing tclclockmod 8.6.704:

ERRINFO: key "FMT_%Y-%m-%d %H:%M:%S" not known in dictionary  while executing "dict get $LocaleFormats $locale $fmtkey"

That appears to be coming from this line:
https://github.com/flightaware/tclclockmod/blob/025c25a/lib/clock.tcl#L826

Any ideas why that might be happening?

[sebres]

Hmm... Normally it is used in catch in order to initialize localized format (and happens only if either mc gets new format, or it is used first time, or catalog gets shimmered for some reasons, e. g. recompile due to epoch change, etc).
But it is not clear to me, why it should cause an error.

At the moment I can imagine one thing only, that could explain that: something trying to produce error message (format it) together with clock, so by first usage of this format in some locale it simply overwrites originated error message.
Something like:

try {
  error test
} on error {} {
  puts [clock format -now -locale de]--$::errorInfo
}

Can you confirm it is scenario like above? I mean no error directly, but remaining as errorInfo (overwriting).

Of course I can (and I will) fix that, but in tcl-core are many things that could overwrite $::errorInfo (for example lazy-loading, unknown handler, etc), so it is advisable to use -errorinfo of options-dict from catch or try instead of $::errorInfo.
So you can also use it as an interim "fix" until I get fixed this overwrite in clock.tcl - diff for example:

-} on error {} {
+} on error {res opts} { 
-  puts [clock format -now -locale de]--$::errorInfo
+  puts [clock format -now -locale de]--[dict get $opts -errorinfo]
 }

[sebres]

OK, 6c276ea should fix that (and does it), but as you can see the test clock-0.2 (I've provided in 8924ca8) that should cover that, is still failing:

https://travis-ci.org/sebres/tclclockmod/jobs/646579330#L431

---- Result was:
{CLOCK badTimeZone :UTC} {time zone ":UTC" not found
    while executing
"LoadTimeZoneFile $timezone "}
---- Result should have been (exact matching):
{EXPERR TEST-ERROR} {ERROR expected error}
==== clock-0.2.vm:0 FAILED

Now it has been overwritten on another place (and same thing you'd discover sporadically even without tclclockmod with stock tcl-clock module).

I'll try to find and solve major things bothering here.

[sebres]

Failed on the next issue - basically c50b98e should fix that, but it does not.

It looks like I found a bug of core Tcl now - Tcl_RestoreInterpState seems to be quite incorrect - value of ::errorInfo is not stored at all, iPtr->errorInfo only - this caused that if it was NULL, a restore from statePtr->errorInfo here:
https://github.com/tcltk/tcl/blob/a25fe0be0feea6adc2f560f2a53b42af71d54383/generic/tclResult.c#L142
would do simply nothing, and an internal trace of ::errorInfo does not change it:
https://github.com/tcltk/tcl/blob/1c9dda6cf6e02b8d8126028ad3477ccd3af42a5f/generic/tclNamesp.c#L619-L623
so it remains unmodified (so remains overwritten value if changed between Tcl_SaveInterpState ... Tcl_RestoreInterpState)

So it looks like either Tcl_RestoreInterpState or trace of ::errorInfo (ErrorInfoRead) are broken.

[bovine]

I think you're right in guessing that the ::errorInfo was getting overwritten during the process of us attempting to log the actual error. In our case, we have a logerr proc that accesses ::errorInfo after invoking logmsg (which is where clock format is getting invoked and overwrites that global variable).

proc logerr {message} {
	logmsg "ERROR: $message" 1
	if {[info exists ::errorInfo]} {
		debug "ERRINFO: $::errorInfo"
	}
}

[sebres]

Thx.

Unless it's not fixed (on my side and in core), you can try something like:

proc logerr {message} {
+	set errInfo $::errorInfo
	logmsg "ERROR: $message" 1
-	if {[info exists ::errorInfo]} {
-		debug "ERRINFO: $::errorInfo"
+	if {$errInfo ne ""} {
+		debug "ERRINFO: $errInfo"
	}
}

By the way: if {[info exists ::errorInfo]} is an atavism, this variable is always created (by read trace), because info exists touches the variable so causes a read trace is invoked.

Also note such usage of ::errorInfo never guarantees you obtain (debug) a details to the given message - it is simply last known error (regardless the supplied message and an "overwrite" issue, so for example if one'd use logerr "test error" without to consider an error was really throwing).

[resuna]

I think saving errorInfo at the first possible point is the best solution, it's the same kind of thing you need to do to safely handle errno in C.

[resuna]

By the way: if {[info exists ::errorInfo]} is an atavism, this variable is always created (by read trace), because info exists touches the variable so causes a read trace is invoked.

I don't think this can be correct:

% unset errorInfo
% info exists errorInfo
0
% puts $::errorInfo
can't read "::errorInfo": no such variable

[sebres]

This is bad idea - unset ::errorInfo destroys a trace - you'll never be able get any error hereafter,

[sebres]

oh... it looks like it has a timing issue additionally (and a trace binding to ErrorInfoRead is still there or gets recreated on error):

% unset errorInfo
% catch {error test}
1
% info exists errorInfo
1
% puts $errorInfo
test
    while executing
"error test"

I thought about something like:

% unset -nocomplain x
% info exists x
0
% proc create-x args {puts **$args**; upvar x x; set x xxx}; trace add variable x read create-x
% info exists x
**x {} read**
1

but don't know exactly what and when would restore the "system" trace back.

[resuna]

[Obsidian:~] peter% tclsh
% info exists errorInfo
0
% puts $errorInfo
can't read "errorInfo": no such variable

Same results if I don't actually "set" it in any way. [info exists errorInfo] doesn't create it. And is absolutely necessary if you don't know whether it exists, because otherwise referencing it is an error.

% unset errorInfo
% puts $bar
can't read "bar": no such variable
% puts $errorInfo
can't read "bar": no such variable
    while executing
"puts $bar"

I see nothing wrong or unexpected.

Your examples also have the results I would expect.

[resuna]

% [Obsidian:~] peter% tclsh
% trace info variable errorInfo
% trace info variable ::errorInfo
% 

[sebres]

And is absolutely necessary if you don't know whether it exists

You are right.

I see nothing wrong or unexpected.
Your examples also have the results I would expect.

A bit unexpected to me was that although it looks like errorInfo is fully traced (and restores read trace by unset), it does not set the value to empty (but it is alright, I was just not aware about that, because preferring options-dict of catch to errorInfo, which is not precise for mentioned reasons).

% trace info variable ::errorInfo

Sure you are unable to get the trace info, because it is a system trace (not tclish command) - https://github.com/tcltk/tcl/blob/1c9dda6cf6e02b8d8126028ad3477ccd3af42a5f/generic/tclNamesp.c#L582-L585

[sebres]

Here is the related bug [554117eddec7220f] in tcl-core.
I have also provided a fix for the Tcl_SaveInterpState/Tcl_RestoreInterpState issue.

[sebres]

It does not look that my fix proposal for bug [554117eddec7220f] will find an acceptance by TCT at the moment (I'd try to introduce new internal command or make a TIP for that later).

Anyway it is fixed now directly in tclclockmod - 1c63b9d.
As one can see it works now (tests clock-0.2 pass too), and because "catched" code pieces are lazy loading, initialization or cached blocks, as expected I have not noticed any performance regression.

So I'll merge that in master (and close the issue) if no objections will follow.

[bovine]

Sounds good. thanks for your work!