[
https://issues.apache.org/jira/browse/LENS-1461?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16131977#comment-16131977
]
Ankit Kailaswar edited comment on LENS-1461 at 8/18/17 9:49 AM:
----------------------------------------------------------------
There were few issues found while persisting service states and using it to
start lens server.
1. Session service is not getting persisted properly on few occasions. session
service try to serialize few sessions which are invalid using its session
handles throwing an exception uncaught at service level. Other services are
getting persisted successfully.
{panel:title=lens server log
|borderStyle=dashed|borderColor=#ccc|titleBGColor=#F7D6C1|bgColor=#FFFFCE}
14 Aug 2017 20:13:49 6daca8db-deb9-4ab0-ba2d-3f5e474ad545
Lens-server-snapshotter-Thread-1 WARN org.apache.lens.server.BaseLensService -
{color:red} *Session cbc183be-8f05-4356-bb56-6ba43217518b not found* {color}
org.apache.hive.service.cli.HiveSQLException: Invalid SessionHandle:
SessionHandle cbc183be-8f05-4356-bb56-6ba43217518b
at
org.apache.hive.service.cli.session.SessionManager.getSession(SessionManager.java:389)
~hive-service-2.1.3-inm.jar:2.1.3-inm
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:366)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.writeExternal(HiveSessionService.java:425)
classes/:na
at
org.apache.lens.server.LensServices.persistState(LensServices.java:369)
classes/:na
at
org.apache.lens.server.LensServices.persistLensServiceState(LensServices.java:354)
classes/:na
at org.apache.lens.server.LensServices.access$100(LensServices.java:63)
classes/:na
at org.apache.lens.server.LensServices$1.run(LensServices.java:305)
classes/:na
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
na:1.8.0_72
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
na:1.8.0_72
at java.lang.Thread.run(Thread.java:745) na:1.8.0_72
14 Aug 2017 20:13:49 ba8c2672-53a0-44ad-9d50-fc53e2286143
grizzly-http-server-12 INFO hive.metastore - Closed a connection to metastore,
current connections: 282
14 Aug 2017 20:13:49 ba8c2672-53a0-44ad-9d50-fc53e2286143
grizzly-http-server-12 INFO org.apache.lens.server.BaseLensService - Closed
session <?xml version="1.0" encoding="UTF-8"
standalone="yes"?><lensSessionHandle><publicId>cbc183be-8f05-4356-bb56-6ba43217518b</publicId><secretId>33a980a2-206c-4dbc-b3d9-ffa3a6b6de87</secretId></lensSessionHandle>
for yoda-admin user
14 Aug 2017 20:13:49 6daca8db-deb9-4ab0-ba2d-3f5e474ad545
Lens-server-snapshotter-Thread-1 {color:red} *ERROR
org.apache.lens.server.LensServices - Error while persisting state for service
session* {color}
javax.ws.rs.ClientErrorException: Session cbc183be-8f05-4356-bb56-6ba43217518b
is invalid <?xml version="1.0" encoding="UTF-8"
standalone="yes"?><lensSessionHandle><publicId>cbc183be-8f05-4356-bb56-6ba43217518b</publicId><secretId>33a980a2-206c-4dbc-b3d9-ffa3a6b6de87</secretId></lensSessionHandle>
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:370)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.writeExternal(HiveSessionService.java:425)
~classes/:na
at
org.apache.lens.server.LensServices.persistState(LensServices.java:369)
classes/:na
at
org.apache.lens.server.LensServices.persistLensServiceState(LensServices.java:354)
classes/:na
at org.apache.lens.server.LensServices.access$100(LensServices.java:63)
classes/:na
at org.apache.lens.server.LensServices$1.run(LensServices.java:305)
classes/:na
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
na:1.8.0_72
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
na:1.8.0_72
at java.lang.Thread.run(Thread.java:745) na:1.8.0_72
Caused by: org.apache.hive.service.cli.HiveSQLException: Invalid SessionHandle:
SessionHandle cbc183be-8f05-4356-bb56-6ba43217518b
at
org.apache.hive.service.cli.session.SessionManager.getSession(SessionManager.java:389)
~hive-service-2.1.3-inm.jar:2.1.3-inm
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:366)
~classes/:na
... 12 common frames omitted
{panel}
This is causing other states to be persisted with updated time while session
service persisted state is older than other causing lens to loose session info
for session created during these period.
This can be fixed by catching exception for invalid sessions and continuing
without serializing it.
2. At the time of startup lens tries to start respective service from last
persisted state for each service. For session service it tries to deserialize
all sessions from persisted state. For few sessions session handles were
serialized as null causing deserialisation of such sessions to to fail and
throw exception caught but not handled causing startup to fail.
{panel:title=lens server log
|borderStyle=dashed|borderColor=#ccc|titleBGColor=#F7D6C1|bgColor=#FFFFCE}
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main {color:red}
*ERROR org.apache.lens.server.LensServices - Could not recover from persisted
state* {color}
java.io.EOFException: null
at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(ObjectInputStream.java:2818)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2874)
~na:1.8.0_72
at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1073)
~na:1.8.0_72
at
org.apache.lens.server.session.LensSessionImpl$LensSessionPersistInfo.readExternal(LensSessionImpl.java:678)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.readExternal(HiveSessionService.java:453)
~classes/:na
at
org.apache.lens.server.LensServices.setupPersistedState(LensServices.java:335)
~classes/:na
at org.apache.lens.server.LensServices.init(LensServices.java:268)
~classes/:na
at org.apache.lens.server.LensServer.startServices(LensServer.java:136)
classes/:na
at org.apache.lens.server.LensServer.<init>(LensServer.java:88)
classes/:na
at
org.apache.lens.server.LensServer.createLensServer(LensServer.java:77)
classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:192)
classes/:na
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main ERROR
org.apache.lens.server.LensServer - Error while creating Lens server
java.lang.RuntimeException: Could not recover from persisted state
at org.apache.lens.server.LensServices.init(LensServices.java:271)
~classes/:na
at org.apache.lens.server.LensServer.startServices(LensServer.java:136)
~classes/:na
at org.apache.lens.server.LensServer.<init>(LensServer.java:88)
~classes/:na
at
org.apache.lens.server.LensServer.createLensServer(LensServer.java:77)
~classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:192)
~classes/:na
Caused by: java.io.EOFException: null
at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(ObjectInputStream.java:2818)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2874)
~na:1.8.0_72
at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1073)
~na:1.8.0_72
at
org.apache.lens.server.session.LensSessionImpl$LensSessionPersistInfo.readExternal(LensSessionImpl.java:678)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.readExternal(HiveSessionService.java:453)
~classes/:na
at
org.apache.lens.server.LensServices.setupPersistedState(LensServices.java:335)
~classes/:na
at org.apache.lens.server.LensServices.init(LensServices.java:268)
~classes/:na
... 4 common frames omitted
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main INFO
org.apache.lens.server.LensServices - {color:red} *Stopping lens server*
{color}
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main ERROR
org.apache.lens.server.LensServer - {color:red} *Error stopping services*
{color}
java.lang.NullPointerException: null
at
org.apache.lens.server.query.QueryExecutionServiceImpl.prepareStopping(QueryExecutionServiceImpl.java:1428)
~classes/:na
at org.apache.lens.server.LensServices.stop(LensServices.java:408)
~classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:202)
~classes/:na
{panel}
root cause :
we persist session service by serializing each active "lens" session. session
service stores lens session handles for each service and uses it get session
info that needs to be serialized. It gets session object for lens in following
sequence,
1. create new hive session handle from lens session handle
2. get hive session object from session manager using this newly created hive
session handle
3. downcast hive session object "HiveSession" to "LensSessionImpl" assuming its
instance of "LensSessionImpl" since it was created as a instance of
"LensSessionImpl"
4. serialize it
It works fine when it is valid session for both hive and lens.
session timeout for lens and hive are 1 day and 3 days respectievely. For a
session which is 2 days old session manager returns valid object for
HiveSession but its no longer a instance of "LensSessionImpl" since lens
session already expired. causing downcasting to initialize lens related member
variable(LensSessionHandle, db, username, password etc) to null causing
deserializer to fail for them.
Proposed Fix,
1. While deserializing we can catch exception and ignoring invalid "lens"
session. This will fix the issue of lens failing to start due to invalid lens
session.
2. downcasting is done in getsession() method in LensSessionImpl and referenced
at lot of places. That might be causing other bugs apart from mentioned above.
We have to avoid downcasting or need to have conditional downcasting using RTTI.
3. We need to have constraint that lens session timeout is always greater than
or equal to hive session timeout. That way session manager will always throw
invalid session exception.
was (Author: ankitkailaswar):
There were few issues found while persisting service states and using it to
start lens server.
1. Session service is not getting persisted properly on few occasions. session
service try to serialize few sessions which are invalid using its session
handles throwing an exception uncaught at service level. Other services are
getting persisted successfully.
{panel:title=lens server log
|borderStyle=dashed|borderColor=#ccc|titleBGColor=#F7D6C1|bgColor=#FFFFCE}
14 Aug 2017 20:13:49 6daca8db-deb9-4ab0-ba2d-3f5e474ad545
Lens-server-snapshotter-Thread-1 WARN org.apache.lens.server.BaseLensService -
{color:red} *Session cbc183be-8f05-4356-bb56-6ba43217518b not found* {color}
org.apache.hive.service.cli.HiveSQLException: Invalid SessionHandle:
SessionHandle cbc183be-8f05-4356-bb56-6ba43217518b
at
org.apache.hive.service.cli.session.SessionManager.getSession(SessionManager.java:389)
~hive-service-2.1.3-inm.jar:2.1.3-inm
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:366)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.writeExternal(HiveSessionService.java:425)
classes/:na
at
org.apache.lens.server.LensServices.persistState(LensServices.java:369)
classes/:na
at
org.apache.lens.server.LensServices.persistLensServiceState(LensServices.java:354)
classes/:na
at org.apache.lens.server.LensServices.access$100(LensServices.java:63)
classes/:na
at org.apache.lens.server.LensServices$1.run(LensServices.java:305)
classes/:na
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
na:1.8.0_72
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
na:1.8.0_72
at java.lang.Thread.run(Thread.java:745) na:1.8.0_72
14 Aug 2017 20:13:49 ba8c2672-53a0-44ad-9d50-fc53e2286143
grizzly-http-server-12 INFO hive.metastore - Closed a connection to metastore,
current connections: 282
14 Aug 2017 20:13:49 ba8c2672-53a0-44ad-9d50-fc53e2286143
grizzly-http-server-12 INFO org.apache.lens.server.BaseLensService - Closed
session <?xml version="1.0" encoding="UTF-8"
standalone="yes"?><lensSessionHandle><publicId>cbc183be-8f05-4356-bb56-6ba43217518b</publicId><secretId>33a980a2-206c-4dbc-b3d9-ffa3a6b6de87</secretId></lensSessionHandle>
for yoda-admin user
14 Aug 2017 20:13:49 6daca8db-deb9-4ab0-ba2d-3f5e474ad545
Lens-server-snapshotter-Thread-1 ERROR org.apache.lens.server.LensServices -
Error while persisting state for service session
javax.ws.rs.ClientErrorException: Session cbc183be-8f05-4356-bb56-6ba43217518b
is invalid <?xml version="1.0" encoding="UTF-8"
standalone="yes"?><lensSessionHandle><publicId>cbc183be-8f05-4356-bb56-6ba43217518b</publicId><secretId>33a980a2-206c-4dbc-b3d9-ffa3a6b6de87</secretId></lensSessionHandle>
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:370)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.writeExternal(HiveSessionService.java:425)
~classes/:na
at
org.apache.lens.server.LensServices.persistState(LensServices.java:369)
classes/:na
at
org.apache.lens.server.LensServices.persistLensServiceState(LensServices.java:354)
classes/:na
at org.apache.lens.server.LensServices.access$100(LensServices.java:63)
classes/:na
at org.apache.lens.server.LensServices$1.run(LensServices.java:305)
classes/:na
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
na:1.8.0_72
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
na:1.8.0_72
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
na:1.8.0_72
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
na:1.8.0_72
at java.lang.Thread.run(Thread.java:745) na:1.8.0_72
Caused by: org.apache.hive.service.cli.HiveSQLException: Invalid SessionHandle:
SessionHandle cbc183be-8f05-4356-bb56-6ba43217518b
at
org.apache.hive.service.cli.session.SessionManager.getSession(SessionManager.java:389)
~hive-service-2.1.3-inm.jar:2.1.3-inm
at
org.apache.lens.server.BaseLensService.getSession(BaseLensService.java:366)
~classes/:na
... 12 common frames omitted
{panel}
This is causing other states to be persisted with updated time while session
service persisted state is older than other causing lens to loose session info
for session created during these period.
This can be fixed by catching exception for invalid sessions and continuing
without serializing it.
2. At the time of startup lens tries to start respective service from last
persisted state for each service. For session service it tries to deserialize
all sessions from persisted state. For few sessions session handles were
serialized as null causing deserialisation of such sessions to to fail and
throw exception caught but not handled causing startup to fail.
{panel:title=lens server log
|borderStyle=dashed|borderColor=#ccc|titleBGColor=#F7D6C1|bgColor=#FFFFCE}
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main {color:red}
*ERROR org.apache.lens.server.LensServices - Could not recover from persisted
state* {color}
java.io.EOFException: null
at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(ObjectInputStream.java:2818)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2874)
~na:1.8.0_72
at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1073)
~na:1.8.0_72
at
org.apache.lens.server.session.LensSessionImpl$LensSessionPersistInfo.readExternal(LensSessionImpl.java:678)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.readExternal(HiveSessionService.java:453)
~classes/:na
at
org.apache.lens.server.LensServices.setupPersistedState(LensServices.java:335)
~classes/:na
at org.apache.lens.server.LensServices.init(LensServices.java:268)
~classes/:na
at org.apache.lens.server.LensServer.startServices(LensServer.java:136)
classes/:na
at org.apache.lens.server.LensServer.<init>(LensServer.java:88)
classes/:na
at
org.apache.lens.server.LensServer.createLensServer(LensServer.java:77)
classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:192)
classes/:na
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main ERROR
org.apache.lens.server.LensServer - Error while creating Lens server
java.lang.RuntimeException: Could not recover from persisted state
at org.apache.lens.server.LensServices.init(LensServices.java:271)
~classes/:na
at org.apache.lens.server.LensServer.startServices(LensServer.java:136)
~classes/:na
at org.apache.lens.server.LensServer.<init>(LensServer.java:88)
~classes/:na
at
org.apache.lens.server.LensServer.createLensServer(LensServer.java:77)
~classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:192)
~classes/:na
Caused by: java.io.EOFException: null
at java.io.DataInputStream.readUnsignedShort(DataInputStream.java:340)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(ObjectInputStream.java:2818)
~na:1.8.0_72
at
java.io.ObjectInputStream$BlockDataInputStream.readUTF(ObjectInputStream.java:2874)
~na:1.8.0_72
at java.io.ObjectInputStream.readUTF(ObjectInputStream.java:1073)
~na:1.8.0_72
at
org.apache.lens.server.session.LensSessionImpl$LensSessionPersistInfo.readExternal(LensSessionImpl.java:678)
~classes/:na
at
org.apache.lens.server.session.HiveSessionService.readExternal(HiveSessionService.java:453)
~classes/:na
at
org.apache.lens.server.LensServices.setupPersistedState(LensServices.java:335)
~classes/:na
at org.apache.lens.server.LensServices.init(LensServices.java:268)
~classes/:na
... 4 common frames omitted
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main INFO
org.apache.lens.server.LensServices - {color:red} *Stopping lens server*
{color}
14 Aug 2017 18:53:16 6236aa77-07ff-424a-be02-1c9b11de8862 main ERROR
org.apache.lens.server.LensServer - {color:red} *Error stopping services*
{color}
java.lang.NullPointerException: null
at
org.apache.lens.server.query.QueryExecutionServiceImpl.prepareStopping(QueryExecutionServiceImpl.java:1428)
~classes/:na
at org.apache.lens.server.LensServices.stop(LensServices.java:408)
~classes/:na
at org.apache.lens.server.LensServer.main(LensServer.java:202)
~classes/:na
{panel}
root cause :
we persist session service by serializing each active "lens" session. session
service stores lens session handles for each service and uses it get session
info that needs to be serialized. It gets session object for lens in following
sequence,
1. create new hive session handle from lens session handle
2. get hive session object from session manager using this newly created hive
session handle
3. downcast hive session object "HiveSession" to "LensSessionImpl" assuming its
instance of "LensSessionImpl" since it was created as a instance of
"LensSessionImpl"
4. serialize it
It works fine when it is valid session for both hive and lens.
session timeout for lens and hive are 1 day and 3 days respectievely. For a
session which is 2 days old session manager returns valid object for
HiveSession but its no longer a instance of "LensSessionImpl" since lens
session already expired. causing downcasting to initialize lens related member
variable(LensSessionHandle, db, username, password etc) to null causing
deserializer to fail for them.
Proposed Fix,
1. While deserializing we can catch exception and ignoring invalid "lens"
session. This will fix the issue of lens failing to start due to invalid lens
session.
2. downcasting is done in getsession() method in LensSessionImpl and referenced
at lot of places. That might be causing other bugs apart from mentioned above.
We have to avoid downcasting or need to have conditional downcasting using RTTI.
3. We need to have constraint that lens session timeout is always greater than
or equal to hive session timeout. That way session manager will always throw
invalid session exception.
> Lens services state are not persisted correctly
> -----------------------------------------------
>
> Key: LENS-1461
> URL: https://issues.apache.org/jira/browse/LENS-1461
> Project: Apache Lens
> Issue Type: Bug
> Components: server
> Reporter: Ankit Kailaswar
> Assignee: Ankit Kailaswar
>
> Lens services state are not persisted correctly causing lens to fail at
> startup.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
