[
https://issues.apache.org/jira/browse/SOLR-17120?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17808791#comment-17808791
]
Calvin Smith commented on SOLR-17120:
-------------------------------------
I can't share the full schema file or the docs unfortunately, and I'm a bit
pressed for time at the moment, but here's what I was able to determine:
- the 8 fields that the error occurs for in my most easily reproducible case
are all single-valued (I only know it is 8 fields due to modifying the code to
skip the null and print to stdout when the error would have happened); 7 of
them are a 'lowercase' field type and the other is 'text_en_splitting_tight'
(as those are defined in the default schema); I wouldn't read much into that
though, as those are common field types in our schema
- I was able to establish that all fields that the error would have happened
for were not set in the doc version in the index (but this doesn't seem to
matter, as I describe below), and all of them had a previous partial update in
the same {{commitWithin}} window that set the field to null
So, for example, if the original full doc in the index contained:
{code:java}
{
"id": "123",
"foo": "bar",
...
}{code}
it did not contain a 'field1', 'field2', ..., 'field8'.
Then there were multiple partial updates, one of which included:
{code:java}
{
"id": "123",
"foo": {"set": "baz"},
"field1": {"set": null},
"field2": {"set": null},
...
"field8": {"set": null}
}{code}
and then after some other updates (of both doc "123", none of which set
field1-field8), there was an update like:
{code:java}
{
"id": "123",
"differentfield1": {
"set": [
348459
]
},
"differentfield2": {
"set": 2
}
}{code}
which does nothing with any of the {{{}field1-field8{}}}, and the
{{NullPointerException}} is thrown then because the older doc returns {{null}}
for whichever of the {{field1-field8}} is processed first.
It doesn't appear to matter whether the document in the index originally has a
value for field1-field8 or not though, as I was able to reproduce the problem
with an identical stack trace even if all those fields had values originally.
So to summarize,
- it doesn't matter if the field in the doc in the index originally has a value
or not
- it happens when there was just 1 prior partial update that set the field to
null
- there are other updates of other fields on that doc (and unrelated updates of
other docs) in between the partial update that sets the field to null and the
doc that causes the {{NullPointerException}}
- the update that causes the error included only updates to fields other than
{{field1-field8}} (the ones that were set to null in the earlier update)
Also, since I didn't include the stack trace here, and I originally gave the
stack trace as for version 8.11.2, here's the stack trace for 9.4.0, which is
the version I've been using for most of my testing:
{noformat}
2024-01-19 18:33:10.160 ERROR (qtp726408598-34) [ x:app t:0.0.0.0-34]
o.a.s.s.HttpSolrCall 500 Exception => java.lang.NullPointerException
at org.apache.solr.update.UpdateLog.applyOlderUpdates(UpdateLog.java:1025)
java.lang.NullPointerException: null
at org.apache.solr.update.UpdateLog.applyOlderUpdates(UpdateLog.java:1025)
~[?:?]
at org.apache.solr.update.UpdateLog.applyPartialUpdates(UpdateLog.java:992)
~[?:?]
at
org.apache.solr.handler.component.RealTimeGetComponent.resolveFullDocument(RealTimeGetComponent.java:476)
~[?:?]
at
org.apache.solr.handler.component.RealTimeGetComponent.getInputDocumentFromTlog(RealTimeGetComponent.java:720)
~[?:?]
at
org.apache.solr.handler.component.RealTimeGetComponent.getInputDocumentFromTlog(RealTimeGetComponent.java:657)
~[?:?]
at
org.apache.solr.handler.component.RealTimeGetComponent.getInputDocument(RealTimeGetComponent.java:773)
~[?:?]
at
org.apache.solr.update.processor.DistributedUpdateProcessor.getUpdatedDocument(DistributedUpdateProcessor.java:788)
~[?:?]
at
org.apache.solr.update.processor.DistributedUpdateProcessor.doVersionAdd(DistributedUpdateProcessor.java:406)
~[?:?]
at
org.apache.solr.update.processor.DistributedUpdateProcessor.lambda$versionAdd$0(DistributedUpdateProcessor.java:356)
~[?:?]
at org.apache.solr.update.VersionBucket.runWithLock(VersionBucket.java:51)
~[?:?]
at
org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:353)
~[?:?]
at
org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:234)
~[?:?]
at
org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:111)
~[?:?]
at
org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.handleAdds(JsonLoader.java:553)
~[?:?]
at
org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.processUpdate(JsonLoader.java:183)
~[?:?]
at
org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.load(JsonLoader.java:151)
~[?:?]
at org.apache.solr.handler.loader.JsonLoader.load(JsonLoader.java:86) ~[?:?]
at
org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:102)
~[?:?]
at
org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:100)
~[?:?]
at
org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:226)
~[?:?]
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2901) ~[?:?]
at
org.apache.solr.servlet.HttpSolrCall.executeCoreRequest(HttpSolrCall.java:875)
~[?:?]
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:561) ~[?:?]
at
org.apache.solr.servlet.SolrDispatchFilter.dispatch(SolrDispatchFilter.java:262)
~[?:?]
at
org.apache.solr.servlet.SolrDispatchFilter.lambda$doFilter$0(SolrDispatchFilter.java:219)
~[?:?]
at
org.apache.solr.servlet.ServletUtils.traceHttpRequestExecution2(ServletUtils.java:246)
~[?:?]
at
org.apache.solr.servlet.ServletUtils.rateLimitRequest(ServletUtils.java:215)
~[?:?]
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:213)
~[?:?]
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:195)
~[?:?]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210)
~[jetty-servlet-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635)
~[jetty-servlet-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527)
~[jetty-servlet-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:598)
~[jetty-security-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484)
~[jetty-servlet-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:149)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.InetAccessHandler.handle(InetAccessHandler.java:228)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:301)
~[jetty-rewrite-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122)
~[jetty-server-10.0.17.jar:10.0.17]
at org.eclipse.jetty.server.Server.handle(Server.java:563)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598)
~[jetty-server-10.0.17.jar:10.0.17]
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753)
~[jetty-server-10.0.17.jar:10.0.17]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287)
~[jetty-server-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
~[jetty-io-10.0.17.jar:10.0.17]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
~[jetty-io-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
~[jetty-io-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:421)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:390)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:199)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:411)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
~[jetty-util-10.0.17.jar:10.0.17]
at
org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
~[jetty-util-10.0.17.jar:10.0.17]
at java.lang.Thread.run(Thread.java:829) [?:?]{noformat}
Thanks again for your help.
> NullPointerException in UpdateLog.applyOlderUpdates in solr 6.6-9.4 involving
> partial updates
> ---------------------------------------------------------------------------------------------
>
> Key: SOLR-17120
> URL: https://issues.apache.org/jira/browse/SOLR-17120
> Project: Solr
> Issue Type: Bug
> Components: update
> Affects Versions: 6.6.2, 8.11.2, 9.4
> Environment: The issue occurred on Linux, CentOS 7.9, with the
> following JDK version:
> {noformat}
> openjdk version "11.0.20" 2023-07-18 LTS
> OpenJDK Runtime Environment (Red_Hat-11.0.20.0.8-1.el7_9) (build
> 11.0.20+8-LTS)
> OpenJDK 64-Bit Server VM (Red_Hat-11.0.20.0.8-1.el7_9) (build 11.0.20+8-LTS,
> mixed mode, sharing){noformat}
> Reporter: Calvin Smith
> Priority: Major
>
> I mailed the solr-users mailing list about this issue, but didn't get any
> responses there, so am creating this issue. The subject of the email thread
> for additional context was "NullPointerException in
> UpdateLog.applyOlderUpdates under solr 8&9 involving partial updates and high
> update load" - link:
> [https://lists.apache.org/thread/n9zm4gocl7cf073syy1159dy6ojjrywl]
> I'm seeing a Solr HTTP 500 error when performing a partial update of a
> document that turns out to triggered by there having been a recent update of
> the same document that included a partial update that set a field to
> {{{}null{}}}. I've observed the behavior in versions 6.6.2, 8.11.2, and
> 9.4.0, which are the only 3 versions I've tried.
> To give an example, an update doc like
>
> {code:java}
> {
> "id": "123",
> "camera_unit": {"set": null}
> }{code}
>
> followed shortly thereafter (not sure of exact timing, but I was using a
> {{commitWithin}} of 600s and the subsequent updates were less than 20 seconds
> later), after some other updates had happened for different documents, there
> was another update of the same document, like
>
> {code:java}
> {
> "id": "123",
> "playlist": {
> "set": [
> 12345
> ]
> },
> "playlist_index_321": {
> "set": 0
> }
> }{code}
>
> This later update may, but doesn't always, cause the
> {{{}NullPointerException{}}}, so there is some other factor such as the state
> of the {{tlog}} that also has to be satisfied for the error to occur.
> The exception is thrown by the following code in {{UpdateLog.java}}
> ({{{}org.apache.solr.update.UpdateLog{}}}):
>
> {code:java}
> /** Add all fields from olderDoc into newerDoc if not already present in
> newerDoc */
> private void applyOlderUpdates(
> SolrDocumentBase<?, ?> newerDoc, SolrInputDocument olderDoc,
> Set<String> mergeFields) {
> for (String fieldName : olderDoc.getFieldNames()) {
> // if the newerDoc has this field, then this field from olderDoc can be
> ignored
> if (!newerDoc.containsKey(fieldName)
> && (mergeFields == null || mergeFields.contains(fieldName))) {
> for (Object val : olderDoc.getFieldValues(fieldName)) {
> newerDoc.addField(fieldName, val);
> }
> }
> }
> }{code}
>
> The exception is due to the inner for statement trying to iterate over the
> {{null}} value being returned by {{{}olderDoc.getFieldValues(fieldName){}}}.
> When I change that method to the following:
>
> {code:java}
> /** Add all fields from olderDoc into newerDoc if not already present in
> newerDoc */
> private void applyOlderUpdates(
> SolrDocumentBase<?, ?> newerDoc, SolrInputDocument olderDoc,
> Set<String> mergeFields) {
> for (String fieldName : olderDoc.getFieldNames()) {
> // if the newerDoc has this field, then this field from olderDoc can be
> ignored
> if (!newerDoc.containsKey(fieldName)
> && (mergeFields == null || mergeFields.contains(fieldName))) {
> Collection<Object> values = olderDoc.getFieldValues(fieldName);
> if (values == null) {
> newerDoc.addField(fieldName, null);
> } else {
> for (Object val : values) {
> newerDoc.addField(fieldName, val);
> }
> }
> }
> }
> }{code}
>
> Then after rebuilding the solr-core JAR with {{./gradlew devFull}} and
> restarting Solr with that custom jar file, I can no longer reproduce the
> error.
> I'm not familiar with the Solr codebase though and am not at all sure that
> {{newerDoc.addField(fieldName, null)}} is what should be done there.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscr...@solr.apache.org
For additional commands, e-mail: issues-h...@solr.apache.org
