Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ZK-5048: MVVM DebuggerFactory should log via SLF4J #3096

Merged
merged 2 commits into from
Dec 18, 2023
Merged

ZK-5048: MVVM DebuggerFactory should log via SLF4J #3096

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e06bd1e
ZK-5048: MVVM DebuggerFactory should log via SLF4J
rebecca0201 Dec 14, 2023
3527f67
Merge branch 'master' into F100-ZK-5048
jumperchen Dec 18, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 11 additions & 0 deletions zkbind/src/main/java/org/zkoss/bind/impl/AbstractBindingHandler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
package org.zkoss.bind.impl;

import java.io.Serializable;
import java.text.MessageFormat;
import java.util.List;
import java.util.Map;
import java.util.Set;
Expand Down Expand Up @@ -66,4 +67,14 @@ protected <K, V> void addBinding(Map<K, List<V>> bindingsMap, K bkey, V binding)
bindingsMap.put(bkey, bindings0);
}
}

protected String getSaveBindingDebugInfo(String operation, Object... args) {
return MessageFormat.format(operation + ":binding.save() "
+ "comp=[{0}],binding=[{1}],command=[{2}],evt=[{3}],notifys=[{4}]", args);
}

protected String getLoadBindingDebugInfo(String operation, Object... args) {
return MessageFormat.format(operation + ":binding.load() "
+ "comp=[{0}],binding=[{1}],context=[{2}],command=[{3}]", args);
}
}
88 changes: 74 additions & 14 deletions zkbind/src/main/java/org/zkoss/bind/impl/BinderImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.net.URLDecoder;
import java.text.MessageFormat;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
Expand Down Expand Up @@ -91,6 +92,8 @@
import org.zkoss.bind.sys.debugger.BindingAnnotationInfoChecker;
import org.zkoss.bind.sys.debugger.BindingExecutionInfoCollector;
import org.zkoss.bind.sys.debugger.DebuggerFactory;
import org.zkoss.bind.sys.debugger.impl.DefaultAnnotationInfoChecker;
import org.zkoss.bind.sys.debugger.impl.DefaultExecutionInfoCollector;
import org.zkoss.bind.sys.debugger.impl.info.AddBindingInfo;
import org.zkoss.bind.sys.debugger.impl.info.AddCommandBindingInfo;
import org.zkoss.bind.sys.debugger.impl.info.CommandInfo;
Expand Down Expand Up @@ -447,8 +450,9 @@ public Map<String, List<Binding>> getBindings(Component comp) {

//called when onPropertyChange is fired to the subscribed event queue
private void doPropertyChange(Object base, String prop) {
String debugInfo = MessageFormat.format("doPropertyChange: base=[{0}],prop=[{1}]", base, prop);
if (_log.isDebugEnabled()) {
_log.debug("doPropertyChange:base=[{}],prop=[{}]", base, prop);
_log.debug(debugInfo);
}

//zk-1468,
Expand All @@ -474,6 +478,8 @@ private void doPropertyChange(Object base, String prop) {
collector.addInfo(new NotifyChangeInfo(_rootComp, base, prop, "Size=" + bindings.size()));
}
doPropertyChange0(base, prop, bindings);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
if (collector != null) {
collector.popStack();
Expand Down Expand Up @@ -505,12 +511,16 @@ private void doPropertyChange0(Object base, String prop, Set<LoadBinding> bindin
BindContextUtil.setConverterArgs(this, comp, ctx, (PropertyBinding) binding);
}

String debugInfo = MessageFormat.format("doPropertyChange:binding.load() "
+ "binding=[{0}],context=[{1}]", binding, ctx);
try {
if (_log.isDebugEnabled()) {
_log.debug("doPropertyChange:binding.load(),binding=[{}],context=[{}]", binding, ctx);
_log.debug(debugInfo);
}
doPrePhase(Phase.LOAD_BINDING, ctx);
binding.load(ctx);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.LOAD_BINDING, ctx);
}
Expand Down Expand Up @@ -1795,8 +1805,10 @@ public void postCommand(String command, Map<String, Object> args) {
private int doCommand(Component comp, CommandBinding commandBinding, String command, Event evt,
Map<String, Object> commandArgs, Set<Property> notifys) {
final String evtnm = evt == null ? null : evt.getName();
String debugInfo = MessageFormat.format("doCommand "
+ "comp=[{0}],command=[{1}],evtnm=[{2}]", comp, command, evtnm);
if (_log.isDebugEnabled()) {
_log.debug("Start doCommand comp=[{}],command=[{}],evtnm=[{}]", comp, command, evtnm);
_log.debug("Start " + debugInfo);
}
BindContext ctx = BindContextUtil.newBindContext(this, commandBinding, false, command, comp, evt);
BindContextUtil.setCommandArgs(this, comp, ctx, commandArgs);
Expand Down Expand Up @@ -1837,6 +1849,8 @@ private int doCommand(Component comp, CommandBinding commandBinding, String comm
_log.debug("End doCommand");
}
return COMMAND_SUCCESS;
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.COMMAND, ctx); //end of Command
}
Expand All @@ -1845,8 +1859,9 @@ private int doCommand(Component comp, CommandBinding commandBinding, String comm

private void doGlobalCommand(Component comp, String command, Event evt, Map<String, Object> commandArgs,
Set<Property> notifys) {
String debugInfo = MessageFormat.format("doGlobalCommand comp=[{0}],command=[{1}]", comp, command);
if (_log.isDebugEnabled()) {
_log.debug("Start doGlobalCommand comp=[{}],command=[{}]", comp, command);
_log.debug("Start " + debugInfo);
}

BindContext ctx = BindContextUtil.newBindContext(this, null, false, command, comp, evt);
Expand All @@ -1862,16 +1877,19 @@ private void doGlobalCommand(Component comp, String command, Event evt, Map<Stri

//execute command
doGlobalCommandExecute(comp, command, commandArgs, ctx, notifys);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.GLOBAL_COMMAND, ctx); //end of Command
}
}

private void doGlobalCommandExecute(Component comp, String command, Map<String, Object> commandArgs,
BindContext ctx, Set<Property> notifys) {
String debugInfo = MessageFormat.format("doGlobalCommandExecute comp=[{0}],command=[{1}]", comp, command);
try {
if (_log.isDebugEnabled()) {
_log.debug("before doGlobalCommandExecute comp=[{}],command=[{}]", comp, command);
_log.debug("before " + debugInfo);
}
doPrePhase(Phase.EXECUTE, ctx);

Expand All @@ -1898,10 +1916,13 @@ private void doGlobalCommandExecute(Component comp, String command, Map<String,
if (_log.isDebugEnabled()) {
_log.debug("no global command method in [{}]", viewModel);
}
debugInfo += MessageFormat.format(",no global command method in viewModel=[{0}]", viewModel);
}
if (_log.isDebugEnabled()) {
_log.debug("after doGlobalCommandExecute notifys=[{}]", notifys);
}
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.EXECUTE, ctx);
}
Expand Down Expand Up @@ -1982,9 +2003,11 @@ private void doLoadEvent(Component comp, Event evt) {
//doCommand -> doValidate
protected boolean doValidate(Component comp, String command, Event evt, BindContext ctx, Set<Property> notifys) {
final Set<Property> validates = new HashSet<Property>();
String debugInfo = MessageFormat.format("doValidate "
+ "comp=[{0}],command=[{1}],evt=[{2}],context=[{3}]", comp, command, evt, ctx);
try {
if (_log.isDebugEnabled()) {
_log.debug("doValidate comp=[{}],command=[{}],evt=[{}],context=[{}]", comp, command, evt, ctx);
_log.debug(debugInfo);
}
doPrePhase(Phase.VALIDATE, ctx);

Expand Down Expand Up @@ -2022,6 +2045,7 @@ public BindingKey getBindingKey(Component comp, String attr) {
if (_log.isDebugEnabled()) {
_log.debug("doValidate validates=[{}]", validates);
}
debugInfo += MessageFormat.format(",validates=[{0}]", validates);
boolean valid = true;

//ZK-878 Exception if binding a form with errorMessage
Expand Down Expand Up @@ -2052,6 +2076,7 @@ public BindingKey getBindingKey(Component comp, String attr) {
return valid;
}
} catch (Exception e) {
_log.error(debugInfo, e);
throw UiException.Aide.wrap(e, e.getMessage());
} finally {
doPostPhase(Phase.VALIDATE, ctx);
Expand All @@ -2076,6 +2101,8 @@ protected ParamCall createParamCall(BindContext ctx) {

protected void doExecute(Component comp, String command, Map<String, Object> commandArgs, BindContext ctx,
Set<Property> notifys) {
String debugInfo = MessageFormat.format("doExecute "
+ "comp=[{0}],command=[{1}],notifys=[{2}]", comp, command, notifys);
try {
Matcher matcher = CALL_OTHER_VM_COMMAND_PATTERN.matcher(command);
if (matcher.find()) {
Expand All @@ -2088,7 +2115,7 @@ protected void doExecute(Component comp, String command, Map<String, Object> com
}
}
if (_log.isDebugEnabled()) {
_log.debug("before doExecute comp=[{}],command=[{}],notifys=[{}]", comp, command, notifys);
_log.debug("before " + debugInfo);
}
doPrePhase(Phase.EXECUTE, ctx);

Expand Down Expand Up @@ -2122,6 +2149,8 @@ protected void doExecute(Component comp, String command, Map<String, Object> com
if (_log.isDebugEnabled()) {
_log.debug("after doExecute notifys=[{}]", notifys);
}
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.EXECUTE, ctx);
}
Expand Down Expand Up @@ -2217,55 +2246,69 @@ private Method getCommandMethod(Class<?> clz, String command, CommandMethodInfoP

//doCommand -> doSaveBefore
protected void doSaveBefore(Component comp, String command, Event evt, BindContext ctx, Set<Property> notifys) {
String debugInfo = MessageFormat.format("doSaveBefore "
+ "comp=[{0}],command=[{1}],evt=[{2}],notifys=[{3}]", comp, command, evt, notifys);
if (_log.isDebugEnabled()) {
_log.debug("doSaveBefore, comp=[{}],command=[{}],evt=[{}],notifys=[{}]", comp, command, evt, notifys);
_log.debug(debugInfo);
}
try {
doPrePhase(Phase.SAVE_BEFORE, ctx);
_propertyBindingHandler.doSaveBefore(comp, command, evt, notifys);
_formBindingHandler.doSaveBefore(comp, command, evt, notifys);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.SAVE_BEFORE, ctx);
}
}

protected void doSaveAfter(Component comp, String command, Event evt, BindContext ctx, Set<Property> notifys) {
String debugInfo = MessageFormat.format("doSaveAfter "
+ "comp=[{0}],command=[{1}],evt=[{2}],notifys=[{3}]", comp, command, evt, notifys);
if (_log.isDebugEnabled()) {
_log.debug("doSaveAfter, comp=[{}],command=[{}],evt=[{}],notifys=[{}]", comp, command, evt, notifys);
_log.debug(debugInfo);
}
try {
doPrePhase(Phase.SAVE_AFTER, ctx);
_propertyBindingHandler.doSaveAfter(comp, command, evt, notifys);
_formBindingHandler.doSaveAfter(comp, command, evt, notifys);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.SAVE_AFTER, ctx);
}

}

protected void doLoadBefore(Component comp, String command, BindContext ctx) {
String debugInfo = MessageFormat.format("doLoadBefore comp=[{0}],command=[{1}]", comp, command);
if (_log.isDebugEnabled()) {
_log.debug("doLoadBefore, comp=[{}],command=[{}]", comp, command);
_log.debug(debugInfo);
}
try {
doPrePhase(Phase.LOAD_BEFORE, ctx);
_propertyBindingHandler.doLoadBefore(comp, command);
_formBindingHandler.doLoadBefore(comp, command);
_childrenBindingHandler.doLoadBefore(comp, command);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.LOAD_BEFORE, ctx);
}
}

protected void doLoadAfter(Component comp, String command, BindContext ctx) {
String debugInfo = MessageFormat.format("doLoadAfter comp=[{0}],command=[{1}]", comp, command);
if (_log.isDebugEnabled()) {
_log.debug("doLoadAfter, comp=[{}],command=[{}]", comp, command);
_log.debug(debugInfo);
}
try {
doPrePhase(Phase.LOAD_AFTER, ctx);
_propertyBindingHandler.doLoadAfter(comp, command);
_formBindingHandler.doLoadAfter(comp, command);
_childrenBindingHandler.doLoadAfter(comp, command);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.LOAD_AFTER, ctx);
}
Expand Down Expand Up @@ -2590,8 +2633,9 @@ public void notifyChange(Object base, String attr) {

private void postGlobalCommand(Component comp, CommandBinding commandBinding, String command, Event evt,
Map<String, Object> args) {
String debugInfo = MessageFormat.format("postGlobalCommand command=[{0}],args=[{1}]", command, args);
if (_log.isDebugEnabled()) {
_log.debug("postGlobalCommand command=[{}], args=[{}]", command, args);
_log.debug(debugInfo);
}

final BindingExecutionInfoCollector collector = getBindingExecutionInfoCollector();
Expand All @@ -2604,6 +2648,8 @@ private void postGlobalCommand(Component comp, CommandBinding commandBinding, St
}

getEventQueue().publish(new GlobalCommandEvent(_rootComp, command, args, evt));
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
if (collector != null) {
collector.popStack();
Expand Down Expand Up @@ -2829,12 +2875,26 @@ public void init(Execution exec, Execution parent) throws Exception {

public BindingExecutionInfoCollector getBindingExecutionInfoCollector() {
DebuggerFactory factory = DebuggerFactory.getInstance();
return factory == null ? null : factory.getExecutionInfoCollector();
if (factory == null) return null;
// ZK-5048: setViewModelClass for MVVM DebuggerFactory to log via SLF4J
BindingExecutionInfoCollector collector = factory.getExecutionInfoCollector();
if (collector instanceof DefaultExecutionInfoCollector) {
Class<?> vmClass = BindUtils.getViewModelClass(getViewModelInView());
((DefaultExecutionInfoCollector) collector).setViewModelClass(vmClass);
}
return collector;
}

public BindingAnnotationInfoChecker getBindingAnnotationInfoChecker() {
DebuggerFactory factory = DebuggerFactory.getInstance();
return factory == null ? null : factory.getAnnotationInfoChecker();
if (factory == null) return null;
// ZK-5048: setViewModelClass for MVVM DebuggerFactory to log via SLF4J
BindingAnnotationInfoChecker checker = factory.getAnnotationInfoChecker();
if (checker instanceof DefaultAnnotationInfoChecker) {
Class<?> vmClass = BindUtils.getViewModelClass(getViewModelInView());
((DefaultAnnotationInfoChecker) checker).setViewModelClass(vmClass);
}
return checker;
}

public String getQueueName() {
Expand Down
6 changes: 4 additions & 2 deletions zkbind/src/main/java/org/zkoss/bind/impl/ChildrenBindingHandler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,13 +88,15 @@ private void doLoadBinding(Component comp, LoadChildrenBinding binding, String c
if (binding instanceof InitChildrenBindingImpl) {
ctx.setAttribute(BinderImpl.IGNORE_TRACKER, Boolean.TRUE); //ignore tracker when doing el , we don't need to track the init
}
String debugInfo = getLoadBindingDebugInfo("doLoadChildrenBinding", comp, binding, ctx, command);
try {
if (_log.isDebugEnabled()) {
_log.debug("doLoadChildrenBinding:binding.load(),component=[{}],binding=[{}],context=[{}],command=[{}]",
comp, binding, ctx, command);
_log.debug(debugInfo);
}
doPrePhase(Phase.LOAD_BINDING, ctx);
binding.load(ctx);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.LOAD_BINDING, ctx);
}
Expand Down
12 changes: 8 additions & 4 deletions zkbind/src/main/java/org/zkoss/bind/impl/FormBindingHandler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -105,13 +105,15 @@ private void doSaveBinding(Component comp, SaveFormBinding binding, String comma
evt);
BindContextUtil.setValidatorArgs(_binder, binding.getComponent(), ctx, binding);
//TODO converter args when we support converter in form
String debugInfo = getSaveBindingDebugInfo("doSaveFormBinding", comp, binding, command, evt, notifys);
try {
if (_log.isDebugEnabled()) {
_log.debug("doSaveFormBinding:binding.save() comp=[{}],binding=[{}],command=[{}],evt=[{}],notifys=[{}]",
comp, binding, command, evt, notifys);
_log.debug(debugInfo);
}
doPrePhase(Phase.SAVE_BINDING, ctx);
binding.save(ctx);
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.SAVE_BINDING, ctx);
}
Expand All @@ -130,10 +132,10 @@ private void doLoadBinding(Component comp, LoadFormBinding binding, String comma
ctx.setAttribute(BinderImpl.IGNORE_TRACKER, Boolean.TRUE); //ignore tracker when doing el , we don't need to track the init
}
//TODO converter args when we support converter in form
String debugInfo = getLoadBindingDebugInfo("doLoadFormBinding", comp, binding, ctx, command);
try {
if (_log.isDebugEnabled()) {
_log.debug("doLoadFormBinding:binding.load(),component=[{}],binding=[{}],context=[{}],command=[{}]",
comp, binding, ctx, command);
_log.debug(debugInfo);
}
doPrePhase(Phase.LOAD_BINDING, ctx);
binding.load(ctx);
Expand All @@ -142,6 +144,8 @@ private void doLoadBinding(Component comp, LoadFormBinding binding, String comma
if (((BinderImpl) binding.getBinder()).hasValidator(binding.getComponent(), binding.getFormId())) {
clearValidationMessages(binding.getBinder(), binding.getComponent(), binding.getFormId());
}
} catch (Exception ex) {
throw new RuntimeException(debugInfo, ex);
} finally {
doPostPhase(Phase.LOAD_BINDING, ctx);
}
Expand Down
Loading
Loading