Re: Use of {} in log statements


RadSolution
 

Bob Said:

"
But this line:

    log.debug("test {0}", 10);

isn’t an error that’s detected when we run the statement. It just happily produces:

  DEBUG - test {0}
"

Surely the intention was to output:

DEBUG - test 10

Somewhere, the substitution of 10 for the {0} isn't happening.
We use this type of thing in C#, but the way it operates has changed over various versions of Visual Studio - has the same thing happened in Java?

Regards, Dave Radcliffe MERG M3666

On Tuesday, 7 January 2020, 16:40:12 GMT, Randall Wood via Groups.Io <rhwood@...> wrote:


It couldn’t hurt to add that check. We can add it to the checkstyle checks (see https://checkstyle.org/config_regexp.html)

Randall

On Jan 7, 2020, at 11:16, Bob Jacobsen <rgj1927@...> wrote:

To follow up on Randall’s comment below, we already run (by default) AllTest et al with an appender set to TRACE, so all the debug statements themselves are being executed _iff_ they are reached in the code:  log.debug in normal code will be executed, log.debug in an exception handler might not (we don’t force throwing of every possible exception in tests)

But this line:

   log.debug("test {0}", 10);

isn’t an error that’s detected when we run the statement. It just happily produces:

  DEBUG - test {0}

I’ve looked at some logs and don’t see any {0} or {1}.  Given that and the code snippets below, I suspect that the statements with {0} and {1} aren’t being executed.  But we wouldn’t necessarily have caught it if they were.

We can add a source-code scan for these similar to the grep below.  Should we?

Bob

On Jan 6, 2020, at 3:06 PM, Randall Wood via Groups.Io <rhwood@...> wrote:

That looks like someone has written logging statements that are not in tested code paths.

I know that sounds somewhat flippant, but since we can either suppress or assert known warning statements, that clearly reveals that someone wrote or edited logging statements without vetting that they log as intended.

Randall
On Jan 6, 2020, at 17:54, Bob Jacobsen <rgj1927@...> wrote:

I find only a few problems with this:

% grep -r '{[0-9][0-9]*}' java/src/ | grep -v .properties | grep log
java/src//jmri/jmrit/dualdecoder/DualDecoderSelectPane.java:                log.warn("Unexpected init programming reply: {0} {1}", value, retcode);
java/src//jmri/jmrit/dualdecoder/DualDecoderSelectPane.java:                    log.debug("Readback error: {0} {1}", retcode, value);
java/src//jmri/jmrit/dualdecoder/DualDecoderSelectPane.java:                    log.debug("Readback error: {0} {1}", retcode, value);
java/src//jmri/jmrit/dualdecoder/DualDecoderSelectPane.java:                    log.debug("Readback error: {0} {1}", retcode, value);
java/src//jmri/jmrit/powerpanel/PowerPane.java:                    log.error("Unexpected state value: {0}", selectMenu.getManager().getPower());
java/src//jmri/jmrit/powerpanel/PowerPane.java:                log.error("Exception trying to turn power on {0}", e);
java/src//jmri/jmrit/powerpanel/PowerPane.java:                log.error("Exception trying to turn power off {0}", e);
java/src//jmri/jmrit/powerpanel/PowerPane.java:                log.error("Exception trying to set power to idle {0}", e);
java/src//jmri/jmrit/powerpanel/PowerPane.java:                log.error("Unexpected state value: {0}", listening.getPower());
java/src//jmri/jmrix/mrc/MrcPacketizer.java:            log.warn("passing to xmit: unexpected exception: {0}", e); //IN18N
java/src//jmri/jmrix/mrc/MrcPacketizer.java:                    log.warn("run: unexpected MrcMessageException: {0}", e); //IN18N
java/src//jmri/jmrix/mrc/MrcMessage.java:            log.error("invalid length in call to ctor: {0}", len);  //IN18N
java/src//jmri/jmrix/mrc/MrcMessage.java:                log.error("Invalid function group: {0}", group);  //IN18N
java/src//jmri/jmrix/mrc/MrcMessage.java:            log.error("ratio number too large: {0}", ratio); //IN18N
java/src//jmri/jmrix/mrc/MrcMessage.java:            log.error("hour number out of range : {0}", hour); //IN18N
java/src//jmri/jmrix/mrc/MrcMessage.java:            log.error("minute number out of range : {0}", minute); //IN18N
java/src//jmri/jmrix/pricom/downloader/LoaderPane.java:        log.debug("Send {0}: {1}", bytes.length, jmri.util.StringUtil.hexStringFromBytes(bytes));
java/src//jmri/jmrix/loconet/downloader/LoaderPane.java:                log.warn("Invalid dmf file 'Options' value {0}",text);
java/src//jmri/jmrix/loconet/downloader/LoaderPane.java:                log.warn("Invalid dmf file 'Erase Blk Size' value {0}",text);

In addition to the Bundle calls, there are a few MessageFormat and regular expression calls that use e.g. ‘{0}’, but they look OK to me.

Bob

On Jan 6, 2020, at 12:04 PM, Andrew Crosland <andrew@...> wrote:

Strangely, when I "Find in Projects" for {0} I get 91 matches in 46 files and see no calls to Bundle.getMessage(). Finding {} stops at 5000 matches :)

I also see {0}, {1}, etc., used in MessageFormat.format() which "googling" tells me is correct.

Andrew


------ Original Message ------
From: "danielb987" <db123@...>
To: jmri@jmri-developers.groups.io
Sent: 06/01/2020 19:48:08
Subject: Re: [jmri-developers] Use of {} in log statements

Bundle.getMessage() uses {0} and {1}, so it may be a confusing between Bundle.getMessage() and log.warn() which hasn't been caught during testing.

Daniel

2020-01-06 20:24 skrev Andrew Crosland:
I see numerous examples throughout the codebase of log statements,
e.g., PowerPane.java
            log.error("Exception trying to turn power on {0}", e);

Or DualDecoderSelectPane.java
            log.warn("Unexpected init programming reply: {0} {1}",
value, retcode);

Unfortunately I had a vague memory of this and searched for {0} to
find examples and spent a bit of time trying to figure out why this
wouldn't work for me. Had I searched for {} it may have been more
fruitful.

I now believe that only empty braces {} actually work. Trying to
specify positional substitution (if that's what it is) with {n} {n+1},
etc just prints "{n}" and "{n+1}" to the log.

To get sensible output the parameters must be listed n the correct
order, e.g., from RestartAction.java
    log.debug("Source: {}; class: {}", e.getSource().toString(),
e.getSource().getClass().getName());
Am I missing something?

Andrew

--
Andrew Crosland


Links:
------
[1] https://jmri-developers.groups.io/g/jmri/message/2515
[2] https://groups.io/mt/69472943/1303822
[3] https://jmri-developers.groups.io/g/jmri/post
[4] https://jmri-developers.groups.io/g/jmri/editsub/1303822
[5] https://jmri-developers.groups.io/g/jmri/leave/defanged






--
Andrew Crosland




--
Bob Jacobsen
rgj1927@...











--
Bob Jacobsen
rgj1927@...






Join jmri@jmri-developers.groups.io to automatically receive all group messages.