Context Navigation

← Previous Ticket
Next Ticket →

Ticket #741 (closed Enhancement: worksforme)

Last modified 10 years ago

misleading log messages identified in core, webclient and webservice plugin

Reported by:	Malte	Owned by:	jri
Priority:	Minor	Milestone:	Release 4.5
Component:	DeepaMehta Standard Distribution	Version:	4.4
Keywords:		Cc:
Complexity:	2	Area:	Application Framework / API
Module:

Description

Three log messages I found a bit misleading:

It is logged:

Invalid access to CompositeValueModel entry "dm4.mail.signature": the caller assumes it to be multiple-value but it is single-value in

.. while one actually used a .putRef() and an addRef() is required. So in fact the opposite of what is logged by dm4-core is the case. Improving this error message for plugin developers seems to be essential (trust- and time-wise).

At another place, the dm4-webclient logs:

07.12.2014 17:17:33 de.deepamehta.plugins.webclient.WebclientPlugin getTopics
INFO: typeUri="dm4.core.topic_type", maxResultSize=100
07.12.2014 17:17:34 de.deepamehta.plugins.webservice.WebservicePlugin getRelatedTopics
INFO: Fetching related topics of topic 4867 (assocTypeUri="dm4.webclient.search_result_item", myRoleTypeUri="null", othersRoleTypeUri="null", othersTopicTypeUri="null", maxResultSize=100)

.. while both lines contain a wrong limit with "maxResultSize=100".

Thanks for making dm4 log messages even more accurate! :)

Change History

comment:1 in reply to: ↑ description Changed 10 years ago by jri

Replying to Malte:

Three log messages I found a bit misleading:

It is logged:
Invalid access to CompositeValueModel entry "dm4.mail.signature": the caller assumes it to be multiple-value but it is single-value in
.. while one actually used a .putRef() and an addRef() is required. So in fact the opposite of what is logged by dm4-core is the case. Improving this error message for plugin developers seems to be essential (trust- and time-wise).

I can't figure it out.
Can you send the stacktrace?

comment:2 in reply to: ↑ description Changed 10 years ago by jri

Replying to Malte:

At another place, the dm4-webclient logs:

07.12.2014 17:17:33 de.deepamehta.plugins.webclient.WebclientPlugin getTopics
INFO: typeUri="dm4.core.topic_type", maxResultSize=100
07.12.2014 17:17:34 de.deepamehta.plugins.webservice.WebservicePlugin getRelatedTopics
INFO: Fetching related topics of topic 4867 (assocTypeUri="dm4.webclient.search_result_item", myRoleTypeUri="null", othersRoleTypeUri="null", othersTopicTypeUri="null", maxResultSize=100)

.. while both lines contain a wrong limit with "maxResultSize=100".

Here the logging is actually correct. The Webclient indeed adds a "max_result_size=100" query parameter to the requests it sends.

However, the "max_result_size" query parameter is not supported anymore by the storage layer. So it is actually useless and should be stripped from the requests sent. I'll fix that in the master branch.

Thank you for reporting!

comment:3 Changed 10 years ago by Malte

Yes, thanks to unlimited buffersize of my terminal, here it is:

07.12.2014 17:10:21 de.deepamehta.core.impl.EmbeddedService createTopic
WARNUNG: ROLLBACK!
07.12.2014 17:10:21 de.deepamehta.plugins.webservice.provider.CatchAllExceptionMapper toResponse
SCHWERWIEGEND: A DeepaMehta resource method or event listener threw an exception resp. an error occurred. Mapping exception/error to response: 500 (Internal Server Error).
java.lang.RuntimeException: Creating topic failed (topic (id=4261, uri="", typeUri="dm4.mail", value="", composite={dm4.mail.signature.preview=topic (id=4242, uri="", typeUri="dm4.mail.signature.preview", value="true", composite={}), relating association (id=4247, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4242)), dm4.mail.date=topic (id=-1, uri="null", typeUri="dm4.mail.date", value="", composite={}), dm4.mail.subject=topic (id=4262, uri="", typeUri="dm4.mail.subject", value="Testmail", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4207, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4202)), dm4.mail.signature=topic (id=3859, uri="null", typeUri="null", value="null", composite={}), dm4.mail.body=topic (id=4233, uri="", typeUri="dm4.mail.body", value="<p>Yo</p>
", composite={}), relating association (id=4238, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4233)), dm4.mail.id=topic (id=-1, uri="null", typeUri="dm4.mail.id", value="", composite={}), dm4.mail.recipient.list=topic (id=4224, uri="", typeUri="dm4.mail.recipient.list", value="true", composite={}), relating association (id=4229, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4224)), dm4.mail.from=topic (id=4271, uri="", typeUri="dm4.mail.from", value="true", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4216, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4211))}))
	at de.deepamehta.core.impl.EmbeddedService.createTopic(EmbeddedService.java:164)
	at de.deepamehta.plugins.mail.MailPlugin.copyMail(MailPlugin.java:246)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:622)
	at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
	at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
	at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
	at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
	at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
	at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
	at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
	at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1480)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1411)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1360)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1350)
	at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.apache.felix.http.base.internal.handler.ServletHandler.doHandle(ServletHandler.java:96)
	at org.apache.felix.http.base.internal.handler.ServletHandler.handle(ServletHandler.java:79)
	at org.apache.felix.http.base.internal.dispatch.ServletPipeline.handle(ServletPipeline.java:42)
	at org.apache.felix.http.base.internal.dispatch.InvocationFilterChain.doFilter(InvocationFilterChain.java:49)
	at org.apache.felix.http.base.internal.dispatch.HttpFilterChain.doFilter(HttpFilterChain.java:33)
	at org.apache.felix.http.base.internal.dispatch.FilterPipeline.dispatch(FilterPipeline.java:48)
	at org.apache.felix.http.base.internal.dispatch.Dispatcher.dispatch(Dispatcher.java:39)
	at org.apache.felix.http.base.internal.DispatcherServlet.service(DispatcherServlet.java:67)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:654)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:445)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:225)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1044)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:372)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:189)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:978)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:255)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
	at org.eclipse.jetty.server.Server.handle(Server.java:369)
	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:486)
	at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:933)
	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:995)
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
	at java.lang.Thread.run(Thread.java:701)
Caused by: java.lang.RuntimeException: Storing composite value of object 4261 failed ({dm4.mail.signature.preview=topic (id=4242, uri="", typeUri="dm4.mail.signature.preview", value="true", composite={}), relating association (id=4247, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4242)), dm4.mail.date=topic (id=-1, uri="null", typeUri="dm4.mail.date", value="", composite={}), dm4.mail.subject=topic (id=4262, uri="", typeUri="dm4.mail.subject", value="Testmail", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4207, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4202)), dm4.mail.signature=topic (id=3859, uri="null", typeUri="null", value="null", composite={}), dm4.mail.body=topic (id=4233, uri="", typeUri="dm4.mail.body", value="<p>Yo</p>
", composite={}), relating association (id=4238, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4233)), dm4.mail.id=topic (id=-1, uri="null", typeUri="dm4.mail.id", value="", composite={}), dm4.mail.recipient.list=topic (id=4224, uri="", typeUri="dm4.mail.recipient.list", value="true", composite={}), relating association (id=4229, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4224)), dm4.mail.from=topic (id=4271, uri="", typeUri="dm4.mail.from", value="true", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4216, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4211))})
	at de.deepamehta.core.impl.ValueStorage.storeCompositeValue(ValueStorage.java:280)
	at de.deepamehta.core.impl.ValueStorage.storeValue(ValueStorage.java:108)
	at de.deepamehta.core.impl.EmbeddedService.topicFactory(EmbeddedService.java:792)
	at de.deepamehta.core.impl.EmbeddedService.createTopic(EmbeddedService.java:156)
	... 52 more
Caused by: java.lang.RuntimeException: Invalid access to CompositeValueModel entry "dm4.mail.signature": the caller assumes it to be multiple-value but it is single-value in
{dm4.mail.signature.preview=topic (id=4242, uri="", typeUri="dm4.mail.signature.preview", value="true", composite={}), relating association (id=4247, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4242)), dm4.mail.date=topic (id=-1, uri="null", typeUri="dm4.mail.date", value="", composite={}), dm4.mail.subject=topic (id=4262, uri="", typeUri="dm4.mail.subject", value="Testmail", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4207, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4202)), dm4.mail.signature=topic (id=3859, uri="null", typeUri="null", value="null", composite={}), dm4.mail.body=topic (id=4233, uri="", typeUri="dm4.mail.body", value="<p>Yo</p>
", composite={}), relating association (id=4238, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4233)), dm4.mail.id=topic (id=-1, uri="null", typeUri="dm4.mail.id", value="", composite={}), dm4.mail.recipient.list=topic (id=4224, uri="", typeUri="dm4.mail.recipient.list", value="true", composite={}), relating association (id=4229, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4224)), dm4.mail.from=topic (id=4271, uri="", typeUri="dm4.mail.from", value="true", composite={dm4.workspaces.workspace=[topic (id=898, uri="de.workspaces.deepamehta", typeUri="dm4.workspaces.workspace", value="DeepaMehta", composite={dm4.workspaces.name=topic (id=899, uri="", typeUri="dm4.workspaces.name", value="DeepaMehta", composite={}), relating association (id=902, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=898),
        topic role (roleTypeUri="dm4.core.child", playerId=899))})]}), relating association (id=4216, uri="", typeUri="dm4.core.composition", value="", composite={},
        topic role (roleTypeUri="dm4.core.parent", playerId=4160),
        topic role (roleTypeUri="dm4.core.child", playerId=4211))}
	at de.deepamehta.core.model.CompositeValueModel.throwInvalidAccess(CompositeValueModel.java:585)
	at de.deepamehta.core.model.CompositeValueModel.getTopics(CompositeValueModel.java:131)
	at de.deepamehta.core.impl.ValueStorage.storeCompositeValue(ValueStorage.java:268)
	... 55 more
Caused by: java.lang.ClassCastException: de.deepamehta.core.model.TopicReferenceModel cannot be cast to java.util.List
	at de.deepamehta.core.model.CompositeValueModel.getTopics(CompositeValueModel.java:128)
	... 56 more

Basically, whenever plugin developers use .putRef() to build up a composite topic, the "caller (in terms of: the plugin developer) assumes that there is a single-valued child but it is not" and whenever the plugin developers use .addRef() to build up a composite module, the "caller assumes that there is a multi-valued child but it is not .." - The current log messages do either (in the putRef case) suggest the opposite or are not directed towards plugin developers (as the "caller").

comment:4 Changed 10 years ago by Jörg Richter <jri@…>

In b8a97ae475396900d11789fe71457f9b903ccc77/deepamehta:

Webclient: do not add max_result_size (#741).

The requests sent by the Webclient do not contain a "max_result_size=100" query parameter as this parameter is not supported anymore by the core anyway.

Thanks to Malte for reporting!

See #741.

comment:5 Changed 10 years ago by jri

After investigating the stacktrace (thank you!) to me it looks like: when copying a mail you used putRef() on a CompositeValueModel to set the signature reference when addRef() is required (because Signature is modelled as "many" for a certain reason). Can you confirm this?

Note: the exception occurs while the composite value is read (in order to store it). Note the getTopics() call in the stacktrace.

Caused by: java.lang.RuntimeException: Invalid access to CompositeValueModel entry "dm4.mail.signature": the caller assumes it to be multiple-value but it is single-value in {... dump of CompositeValueModel follows}
        at de.deepamehta.core.model.CompositeValueModel.throwInvalidAccess(CompositeValueModel.java:585)
        at de.deepamehta.core.model.CompositeValueModel.getTopics(CompositeValueModel.java:131)
        at de.deepamehta.core.impl.ValueStorage.storeCompositeValue(ValueStorage.java:268)

At this time the model is invalid as DM finds a single object for "dm4.mail.signature" when a list of objects is expected.

So, the exception message is meant to be read as "the caller assumes it to be multiple-value {because it is modeled this way} but it is single-value in {the composite value model the caller has passed}"

Note: at the time when you construct the invalid model -- by using putRef() instead of addRef() -- no exception is raised.

This is indeed kind of a bad situation but not easy to change, as with the current DM architecture a model object has no knowledge about the type definitions (in particular the "one"/"many" configuration).

We could address this issue in a separate ticket "DM should not allow the developer to construct a model object that is not conform to the type definition".

In the meantime I could try to reformulate the exception message to be more clear.