Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 423290

Summary:

Meta File Error, cannot read JSON file; user.json: A JSONObject text must begin with '{' at character 0

Product:

[ECD] Orion

Reporter:

Adrian Aichner <adrian.aichner>

Component:

Server

Assignee:

Anthony Hunter <ahunter.eclipse>

Status:

RESOLVED FIXED

QA Contact:

Severity:

normal

Priority:

CC:

ahunter.eclipse, john.arthorne, mamacdon

Version:

unspecified

Target Milestone:

5.0 RC1

Hardware:

OS:

Windows XP

Whiteboard:

Attachments:

Description	Flags
system environment information requested in c11.	none

Description Adrian Aichner

2013-12-05 05:49:35 EST

I get this during a git repository [Fetch] when an alert asks me to ...

Would you like to add ssh-rsa key for host github.com to continue operation? Key fingerpt is 16:27:ac:a5:76:28:2d:36:63:1b:56:4d:eb:df:a6:48.

I am runing orion from a bash with my user credentials ssh-agent-ized with my key used for github.

2013-12-05 11:32:27.776 [qtp12390852-49] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
2013-12-05 11:32:27.794 [qtp12390852-49] INFO  org.eclipse.orion.server.config - SimpleMetaStore.readUser: could not read user adrian

My user.json starts with (... added by me)

{
    "FullName": "Adrian Aichner",
    "OrionVersion": 4,
    "Properties": {
        "/operations//task/id/0M...": "{\"Name\":\"Pushing remote: origin/master\",\"expires\":13...}",


and end with:

    "profileProperties": {
        "openid": "https://www.google.com/accounts/o8/id?id=...",
        "passwordResetId": "13...-0.8..."
    }
}

I get these JSON errors very seldomly and repeating the fetch does not report them.

I have gone through a metadata migration but all else seems to work.

I have not been successful to add that ssh-rsa key yet, although I do push to multiple repos at github.com.

Comment 1 Anthony Hunter

2013-12-05 10:03:18 EST

(In reply to Adrian Aichner from comment #0)
> 2013-12-05 11:32:27.776 [qtp12390852-49] ERROR
> org.eclipse.orion.server.config - Meta File Error, cannot read JSON file
> /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text
> must begin with '{' at character 0
> 2013-12-05 11:32:27.794 [qtp12390852-49] INFO 
> org.eclipse.orion.server.config - SimpleMetaStore.readUser: could not read
> user adrian

So you are saying that /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json *does* have a '{' at character 0 in the file?

Does the /var/home/adrian/eclipse-orion-ws/.metadata/.log have any messages in it? Can you attach the full stack trace?

Comment 2 Adrian Aichner

2013-12-06 06:11:41 EST

Ah, yes, { at char 0.

I don't see anything interesting in .log, but here is the relevant section (by timestamp, ... are my edits)

!ENTRY org.eclipse.orion.server.configurator 1 0 2013-12-05 11:30:31.838
!MESSAGE Keystore absolute path is ...
!SESSION 2013-12-05 13:50:16.781 ----------------------------------------------\
-
eclipse.buildId=unknown
java.version=1.7.0_25
java.vendor=Oracle Corporation
BootLoader constants: OS=linux, ARCH=x86, WS=gtk, NL=de_DE
Framework arguments:  -product org.eclipse.orion.product
Command-line arguments:  -dev file:/var/home/adrian/workspace-kepler-4/.metadat\
a/.plugins/org.eclipse.pde.core/web-ide/dev.properties -os linux -ws gtk -arch \
x86 -consoleLog -data /var/home/adrian/eclipse-orion-ws -clean -product org.ecl\
ipse.orion.product

!ENTRY org.eclipse.orion.server.configurator 1 0 2013-12-05 13:50:32.061
!MESSAGE Https is enabled

!ENTRY org.eclipse.orion.server.configurator 1 0 2013-12-05 13:50:32.078
!MESSAGE Keystore absolute path is ...

=============================================================================
I only see one old stack trace involving /json/i, which is probably irrelevant by now with my frequent git pull from master.
=============================================================================

------
!ENTRY org.eclipse.orion.server.core 4 0 2013-11-18 18:09:14.971
!MESSAGE Internal server error
!STACK 0
java.lang.RuntimeException: Meta File Error, could not build JSON
        at org.eclipse.orion.internal.server.core.metastore.SimpleMetaStoreUtil.readMetaFile(SimpleMetaStoreUtil.java:451)
        at org.eclipse.orion.internal.server.core.metastore.SimpleMetaStore.readUser(SimpleMetaStore.java:435)
        at org.eclipse.orion.server.git.servlets.GitCloneHandlerV1.isAccessAllowed(GitCloneHandlerV1.java:427)
        at org.eclipse.orion.server.git.servlets.GitCloneHandlerV1.handleGet(GitCloneHandlerV1.java:283)
        at org.eclipse.orion.server.git.servlets.GitCloneHandlerV1.handleRequest(GitCloneHandlerV1.java:68)
        at org.eclipse.orion.server.git.servlets.GitCloneHandlerV1.handleRequest(GitCloneHandlerV1.java:1)
        at org.eclipse.orion.server.git.servlets.GitHandlerV1.handleRequest(GitHandlerV1.java:68)
        at org.eclipse.orion.server.git.servlets.GitHandlerV1.handleRequest(GitHandlerV1.java:1)
        at org.eclipse.orion.server.git.servlets.ServletGitHandler.handleRequest(ServletGitHandler.java:49)
        at org.eclipse.orion.server.git.servlets.ServletGitHandler.handleRequest(ServletGitHandler.java:1)
        at org.eclipse.orion.server.git.servlets.GitServlet.doGet(GitServlet.java:39)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:735)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
        at org.eclipse.equinox.http.registry.internal.ServletManager$ServletWrapper.service(ServletManager.java:180)
        at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:38)
        at org.eclipse.orion.server.configurator.servlet.LoggedInUserFilter.doFilter(LoggedInUserFilter.java:61)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.orion.internal.server.hosting.HostedSiteRequestFilter.doFilter(HostedSiteRequestFilter.java:50)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.orion.server.configurator.servlet.WelcomeFileFilter.doFilter(WelcomeFileFilter.java:99)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82)
        at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:280)
        at org.eclipse.orion.server.configurator.servlet.ExcludedExtensionGzipFilter.doFilter(ExcludedExtensionGzipFilter.java:42)
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173)
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81)
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35)
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:132)
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:68)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
        at org.eclipse.equinox.http.jetty.internal.HttpServerManager$InternalHttpServiceServlet.service(HttpServerManager.java:386)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:457)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
        at org.eclipse.jetty.server.Server.handle(Server.java:368)
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
        at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
        at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
        at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
        at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
        at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:670)
        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:724)
Caused by: org.json.JSONException: Unterminated string at character 16384
        at org.json.JSONTokener.syntaxError(JSONTokener.java:412)
        at org.json.JSONTokener.nextString(JSONTokener.java:243)
        at org.json.JSONTokener.nextValue(JSONTokener.java:343)
        at org.json.JSONObject.<init>(JSONObject.java:190)
        at org.json.JSONTokener.nextValue(JSONTokener.java:346)
        at org.json.JSONObject.<init>(JSONObject.java:205)
        at org.json.JSONObject.<init>(JSONObject.java:419)
        at org.eclipse.orion.internal.server.core.metastore.SimpleMetaStoreUtil.readMetaFile(SimpleMetaStoreUtil.java:445)
        ... 67 more
!SESSION 2013-11-18 20:07:24.301 -----------------------------------------------

Comment 3 Adrian Aichner

2013-12-06 08:23:32 EST

OK, here is something more specific, which happened today:

I found this in ~/eclipse-orion-ws/ad/adrian/user.json:

        "operations//task/id/YJa6PpZdABMQAY_rVOF_VA": "{\"Name\":\"Fetching remote: origin/master\",\"expires\":1386846717478}",
        "operations//task/id/YJa6PpZdABMQAY_rVOF_VA": "{\"Name\":\"Pushing remote: anaran/master\",\"expires\":1386843363293}",

I made a backup of user.json, deleted both keys from the file.
After a server restart orion seems to function normally again.

Finding the duplicates was easy based on following console log:

2013-12-06 12:53:08.603 [Start Level Event Dispatcher] INFO  org.eclipse.orion.server.config - Server configuration file loaded from: /var/home/adrian/git/org.eclipse.orion.client/bun\
dles/org.eclipse.orion.client.core/web-ide.conf
2013-12-06 12:53:09.715 [Worker-0] INFO  org.eclipse.orion.server.config - Initializing server metadata store
2013-12-06 12:53:09.747 [Worker-0] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Duplicate key \
"operations//task/id/YJa6PpZdABMQAY_rVOF_VA"
2013-12-06 12:53:09.748 [Worker-0] INFO  org.eclipse.orion.server.config - SimpleMetaStore.readUser: could not read user adrian
!SESSION 2013-12-06 12:53:06.404 -----------------------------------------------
eclipse.buildId=unknown
java.version=1.7.0_25
java.vendor=Oracle Corporation
BootLoader constants: OS=linux, ARCH=x86, WS=gtk, NL=de_DE
Framework arguments:  -product org.eclipse.orion.product
Command-line arguments:  -dev file:/var/home/adrian/workspace-kepler-4/.metadata/.plugins/org.eclipse.pde.core/web-ide/dev.properties -os linux -ws gtk -arch x86 -consoleLog -data /va\
r/home/adrian/eclipse-orion-ws -clean -product org.eclipse.orion.product

!ENTRY org.eclipse.core.jobs 4 2 2013-12-06 12:53:09.770
!MESSAGE An internal error occurred during: "Indexing".
!STACK 0
java.lang.NullPointerException
        at org.eclipse.orion.internal.server.search.Indexer.indexUser(Indexer.java:126)
        at org.eclipse.orion.internal.server.search.Indexer.run(Indexer.java:293)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:53)

!ENTRY org.eclipse.orion.server.configurator 1 0 2013-12-06 12:53:09.938
!MESSAGE Https is enabled

!ENTRY org.eclipse.orion.server.configurator 1 0 2013-12-06 12:53:09.939
!MESSAGE Keystore absolute path is ...
2013-12-06 12:53:26.256 [qtp11142439-29] INFO  org.eclipse.orion.server.login - Persona auth request for configured host. Sending audience ...
2013-12-06 12:53:27.880 [qtp11142439-29] INFO  org.eclipse.orion.server.login - Persona verification succeeded: ...
2013-12-06 12:53:27.883 [qtp11142439-29] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Duplicat\
e key "operations//task/id/YJa6PpZdABMQAY_rVOF_VA"
2013-12-06 12:53:27.894 [qtp11142439-29] WARN  o.e.jetty.servlet.ServletHandler - /login/persona
java.lang.RuntimeException: SimpleUserProfileNode.init: user.json is blank for user adrian
        at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileNode.init(SimpleUserProfileNode.java:64) ~[na:na]
        at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileNode.<init>(SimpleUserProfileNode.java:50) ~[na:na]
        at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileRoot.getUserProfileNode(SimpleUserProfileRoot.java:56) ~[na:na]
        at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserCredentialsService.getUser(SimpleUserCredentialsService.java:245) ~[na:na]
        at org.eclipse.orion.server.authentication.formpersona.PersonaHelper.handleCredentialsAndLogin(PersonaHelper.java:149) ~[na:na]
        at org.eclipse.orion.server.authentication.formopenid.FormOpenIdLoginServlet.doPost(FormOpenIdLoginServlet.java:123) ~[na:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:755) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:38) ~[na:na]
        at org.eclipse.orion.internal.server.hosting.HostedSiteRequestFilter.doFilter(HostedSiteRequestFilter.java:52) ~[na:na]
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
        at org.eclipse.orion.server.configurator.servlet.WelcomeFileFilter.doFilter(WelcomeFileFilter.java:99) ~[na:na]
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
        at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73) ~[na:na]
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
        at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73) ~[na:na]
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
        at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82) ~[na:na]
        at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:242) ~[na:na]
        at org.eclipse.orion.server.configurator.servlet.ExcludedExtensionGzipFilter.doFilter(ExcludedExtensionGzipFilter.java:42) ~[na:na]
        at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:132) ~[na:na]
        at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:68) ~[na:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
        at org.eclipse.equinox.http.jetty.internal.HttpServerManager$InternalHttpServiceServlet.service(HttpServerManager.java:386) ~[org.eclipse.equinox.http.jetty_3.0.100.v20130327-\
1442.jar:na]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:457) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.Server.handle(Server.java:368) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:953) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1014) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:861) ~[org.eclipse.jetty.http_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) ~[org.eclipse.jetty.http_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:670) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) ~[na:na]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) ~[na:na]
        at java.lang.Thread.run(Thread.java:724) ~[na:1.7.0_25]

Comment 4 Adrian Aichner

2013-12-06 18:45:38 EST

More of this:

2013-12-07 00:18:33.211 [qtp27070532-337] ERROR org.eclipse.orion.server.config\
 - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/\
adrian/user.json: A JSONObject text must begin with '{' at character 0
2013-12-07 00:18:33.292 [qtp27070532-336] ERROR org.eclipse.orion.server.config\
 - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/\
adrian/user.json: A JSONObject text must begin with '{' at character 0
2013-12-07 00:21:34.769 [qtp27070532-373] ERROR org.eclipse.orion.server.config\
 - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/\
adrian/user.json: Expected a ',' or '}' at character 40966

For this one at character 40966, I have inserted a ^ character where that character is (as counted by Emacs, C-u 4 0 9 6 6 C-f):

        "operations//task/id/wEkuy45WABMQAf8D8HTTrg": "{\"Name\":\"Pushing remo\
te: origin/devtools_import_export\",\"expires\":1386070506269}",
        "operations//task/id/wEleCLBZABMQAfGAMZqANg":^ "{\"Name\":\"Fetching rem\
ote: origin/master\",\"expires\":1386414635531}",
        "operations//task/id/wEwvPwdSABMQAZLfgevKwg": "{\"Name\":\"Pushing remo\
te: origin/master\",\"expires\":1385572483026}",

I have now also run [Remove completed] from /operations/list.html (after above error occured).

Comment 5 Adrian Aichner

2013-12-06 19:06:26 EST

Immediately after [Remove completed] in /operations/list.html
I get this new one:

403:2013-12-07 00:58:04.127 [qtp27070532-448] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 8192 (see ^ again).


Hmmh, 40966/8192
5.000732421875

This "E" entry looks like old metadata to me.

Should that still be there after me running metadata migration (which I did when the mail came out on orion-dev)?

            "E": {
                "HostHint": "self",
                "Id": "E",
                "Mappings": "[{\"Source\":\"/\",\"Target\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.orion\
.client.ui/web/index.html\"},{\"Source\":\"/\",\"Target\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.orion.\
client.ui/web\"},{\"Source\":\"/\",\"Target\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.orion.client.core/\
web\"},{\"Source\":\"/\",\"Target\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.orion.client.editor/web\"},{\
\"Source\":\"/file\",\"Target\":\"http://localhost:8443/file\"},{\"Source\":\"/prefs\",\"Target\":\"http://localhost:84\
43/prefs\"},{\"Source\":\"/workspace\",\"Target\":\"http://localhost:8443/workspace\"},{\"Source\":\"/users\",\"Target\\
":\"http://localhost:8443/users\"},{\"Source\":\"/authenticationPlugin.html\",\"Target\":\"http://localhost:8443/authen\
ticationPlugin.html\"},{\"Source\":\"/login\",\"Target\":\"http://localhost:8443/login\"},{\"Source\":\"/loginstatic\",\
\"Target\":\"http://localhost:8443/loginstatic\"},{\"Source\":\"/useremailconfirmation\",\"Target\":\"http://localhost:\
8443/useremailconfirmation\"},{\"Source\":\"/site\",\"Target\":\"http://localhost:8443/site\"},{\"Source\":\"/\",\"Targ\
et\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.orion.client.git/web\"},{\"Source\":\"/gitapi\",\"Target\":\
\"http://localhost:8443/gitapi\"},{\"Source\":\"/\",\"Target\":\"/adrian/old-serverworkspace-on/F/bundles/org.eclipse.o\
rion.client.users/web\"},{\"Source\":\"/xfer\",\"Target\":\"http://localhost:8443/xfer\"},{\"Source\":\"/filesearch\",\\
"Target\":\"http://localhost:8443/filesearch\"},{\"Source\":\"/index.jsp\",\"Target\":\"http://localhost:8443/index.jsp\
\"},{\"Source\":\"/plugins/git\",\"Target\":\"http://localhost:8443/plugins/git\"},{\"Source\":\"/plugins/user\",\"Targ\
et\":\"http://localhost:8443/plugins/user\"},{\"Source\":\"/logout\",\"Target\":\"http://localhost:8443/logout\"},{\"So\
urce\":\"/mixlogin/manageopenids\",\"Target\":\"http://localhost:8443/mixlogin/manageopenids\"},{\"Source\":\"/openids\\
",\"Target\":\"http://lo^calhost\
:8443/openids\"},{\"Source\":\"/task\",\"Target\":\"http://localhost:8443/task\\
"},{\"Source\":\"/help\",\"Target\":\"http://localhost:8443/help\"},{\"Source\"\
:\"/old-serverworkspace-on\",\"Target\":\"/adrian/old-serverworkspace-on\"}]",
                "Name": "self",
                "Workspace": "adrian-OrionContent"
            },

Comment 6 Anthony Hunter

2013-12-09 12:20:22 EST

(In reply to Adrian Aichner from comment #5)
> This "E" entry looks like old metadata to me.

In this case this is a sites entry so the Id : E is correct in this case.

Comment 7 Anthony Hunter

2013-12-09 12:23:29 EST

Following along, I cannot tell if this is the same issue as bug 422193 where one of the operations became corrupted by one character.

I think you have already done this, but you can delete all the operations entries and then see if the user.json file is good again.

Once you do have a good user.json again, it would be good to know if the git operations are what is corrupting your user.json again.

Comment 8 Adrian Aichner

2013-12-11 17:16:23 EST

Hi Anthony!

I still have left old operations in user.json with expires properties of e.g.
new Date(1384000397619)
Sat Nov 09 2013 13:33:17 GMT+0100 (Westeuropäische Normalzeit)
new Date(1383957544228)
Sat Nov 09 2013 01:39:04 GMT+0100 (Westeuropäische Normalzeit)

I only carefully removed two operations which had identical task id.

Since then I have seen JSON errors, typically after
git fetch
git merge
operations remove completed

I tried to provoke the problem again today, and there where changes to fetch and merge (ff) but no JSON errors so far.

I will keep you informed.

Adrian

Comment 9 Anthony Hunter

2014-01-20 13:58:59 EST

(In reply to Adrian Aichner from comment #8)
> I will keep you informed.
> 
> Adrian

Any further word on this issue?

Comment 10 Adrian Aichner

2014-01-20 14:53:11 EST

(In reply to Anthony Hunter from comment #9)
> (In reply to Adrian Aichner from comment #8)
> > I will keep you informed.
> > 
> > Adrian
> 
> Any further word on this issue?

My logs say I still see this about once a week.
I am running HEAD of master.

nohup20140108T111430+0100.out:4716:2014-01-08 11:01:50.087 [qtp28914383-1460] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 24576
nohup20140116T105803+0100.out:482:2014-01-15 17:55:23.446 [qtp26886132-241] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:769:2014-01-20 02:53:35.828 [qtp20266009-320] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:858:2014-01-20 03:37:42.950 [qtp20266009-926] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
adrian@tanga:~$

Comment 11 Anthony Hunter

2014-01-21 14:11:15 EST

Hi Adrian, can you run:

% env > Bug423290.txt 

and email me the result?

There may be something with your LANG or LANGUAGE settings on your Linux machine that I can try to duplicate here. What operating system / version is this?

Comment 12 Adrian Aichner

2014-01-21 18:48:10 EST

Created attachment 239209 [details]
system environment information requested in c11.

Comment 13 Adrian Aichner

2014-01-21 18:49:02 EST

(In reply to Anthony Hunter from comment #11)
> Hi Adrian, can you run:
> 
> % env > Bug423290.txt 
> 
> and email me the result?
> 
> There may be something with your LANG or LANGUAGE settings on your Linux
> machine that I can try to duplicate here. What operating system / version is
> this?


OK, I have uploaded it.

I captured information in the file with the script command, so that you can see all I typed and all the system printed to stdout and stderr.

As a consequence it contains some special escape sequences as well.

Comment 14 Adrian Aichner

2014-01-22 08:21:20 EST

Prompted by my login attempts via persona being ignored I found following corruption in my user.json file.
Luckily the file is not blank, as the error message states.
Perhaps the error message should be re-worded.
I am delimiting the excerpt with markdown syntax.
Beginning of line has following one-based offset of characters into the file, as reported by Emacs:
Char: SPC (32, #o40, #x20) point=40944 of 54612 (75%) column=0

```
        "operatio   "operations//task/id/kP42_m1wABMQAcaIc2AGNQ": "{\"Name\":\"Fetching remote: origin/master\",\"expires\":1388915151131}",
```

End of nohup.out of my orion server:

2014-01-22 13:47:17.447 [qtp20266009-2631] INFO  org.eclipse.orion.server.login - Persona verification succeeded: user@email.address
2014-01-22 13:47:17.458 [qtp20266009-2631] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Expected a ':' after a key at character 40965
2014-01-22 13:47:17.464 [qtp20266009-2631] WARN  o.e.jetty.servlet.ServletHandler - /login/persona
java.lang.RuntimeException: SimpleUserProfileNode.init: user.json is blank for user adrian
	at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileNode.init(SimpleUserProfileNode.java:64) ~[na:na]
	at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileNode.<init>(SimpleUserProfileNode.java:50) ~[na:na]
	at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserProfileRoot.getUserProfileNode(SimpleUserProfileRoot.java:56) ~[na:na]
	at org.eclipse.orion.internal.server.useradmin.simple.SimpleUserCredentialsService.getUser(SimpleUserCredentialsService.java:245) ~[na:na]
	at org.eclipse.orion.server.authentication.formpersona.PersonaHelper.handleCredentialsAndLogin(PersonaHelper.java:149) ~[na:na]
	at org.eclipse.orion.server.authentication.formopenid.FormOpenIdLoginServlet.doPost(FormOpenIdLoginServlet.java:123) ~[na:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:755) ~[javax.servlet_3.0.0.v201112011016.jar:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
	at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:38) ~[na:na]
	at org.eclipse.orion.internal.server.hosting.HostedSiteRequestFilter.doFilter(HostedSiteRequestFilter.java:52) ~[na:na]
	at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
	at org.eclipse.orion.server.configurator.servlet.WelcomeFileFilter.doFilter(WelcomeFileFilter.java:99) ~[na:na]
	at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
	at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73) ~[na:na]
	at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
	at org.eclipse.orion.server.configurator.servlet.CacheFilter.doFilter(CacheFilter.java:73) ~[na:na]
	at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
	at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82) ~[na:na]
	at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:242) ~[na:na]
	at org.eclipse.orion.server.configurator.servlet.ExcludedExtensionGzipFilter.doFilter(ExcludedExtensionGzipFilter.java:42) ~[na:na]
	at org.eclipse.equinox.http.registry.internal.FilterManager$FilterWrapper.doFilter(FilterManager.java:173) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterRegistration.doFilter(FilterRegistration.java:81) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:35) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:132) ~[na:na]
	at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:68) ~[na:na]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:848) ~[javax.servlet_3.0.0.v201112011016.jar:na]
	at org.eclipse.equinox.http.jetty.internal.HttpServerManager$InternalHttpServiceServlet.service(HttpServerManager.java:386) ~[org.eclipse.equinox.http.jetty_3.0.100.v20130327-1442.jar:na]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:457) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1075) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384) ~[org.eclipse.jetty.servlet_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.Server.handle(Server.java:368) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:953) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1014) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:861) ~[org.eclipse.jetty.http_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240) ~[org.eclipse.jetty.http_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.server.ssl.SslSocketConnector$SslConnectorEndPoint.run(SslSocketConnector.java:670) ~[org.eclipse.jetty.server_8.1.10.v20130312.jar:8.1.10.v20130312]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) ~[na:na]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) ~[na:na]
	at java.lang.Thread.run(Thread.java:724) ~[na:1.7.0_25]

Comment 15 Adrian Aichner

2014-01-22 08:27:40 EST

(In reply to Adrian Aichner from comment #14)
> Prompted by my login attempts via persona being ignored I found following
> corruption in my user.json file.
> Luckily the file is not blank, as the error message states.
> Perhaps the error message should be re-worded.
> I am delimiting the excerpt with markdown syntax.
> Beginning of line has following one-based offset of characters into the
> file, as reported by Emacs:
> Char: SPC (32, #o40, #x20) point=40944 of 54612 (75%) column=0
> 
> ```
>         "operatio   "operations//task/id/kP42_m1wABMQAcaIc2AGNQ":
> "{\"Name\":\"Fetching remote: origin/master\",\"expires\":1388915151131}",
> ```

After I delete the corrupted line above from user.json I am able to access my orion session again, without server restart, and without being prompted for persona login.

Apparently I am still authenticated.

I feel lucky.

Comment 16 Anthony Hunter

2014-01-22 11:42:34 EST

I have discovered that this problem can be duplicated by double clicking on the fetch button. Looks like all the buttons, especially fetch and pull can be clicked multiple times while an operation has already been started.

This causes two git fetch operations to start simultaneously. 

If I do this enough times, I eventually get your error where one operation is writing the user.json and the other is reading it and finding an empty file.

I can also multi click the pull button on multiple clones displayed on the Repositories page, starting a huge number of pull operations all running at the same time. Eventually one of the operations steps on the other and introduces a corruption in the user.json as you have discovered.

I have raised Bug 426379 for the client issue, I will resolve the server side problem with this bug.

Comment 17 Adrian Aichner

2014-01-22 13:00:06 EST

(In reply to Anthony Hunter from comment #16)
> I have discovered that this problem can be duplicated by double clicking on
> the fetch button. Looks like all the buttons, especially fetch and pull can
> be clicked multiple times while an operation has already been started.
> 
> This causes two git fetch operations to start simultaneously. 
> 
> If I do this enough times, I eventually get your error where one operation
> is writing the user.json and the other is reading it and finding an empty
> file.
> 
> I can also multi click the pull button on multiple clones displayed on the
> Repositories page, starting a huge number of pull operations all running at
> the same time. Eventually one of the operations steps on the other and
> introduces a corruption in the user.json as you have discovered.
> 
> I have raised Bug 426379 for the client issue, I will resolve the server
> side problem with this bug.

Glad you tracked this down!

Can you also explain why I can readily produce a variation of the error by running

Background Operations	Ctrl+Shift+O

It does not happened until a few operations have accumulated after I
[Remove Completed]
operations.

Here is my latest incident (starting at 18:50:50):

nohup.out:3146:2014-01-22 13:47:17.458 [qtp20266009-2631] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Expected a ':' after a key at character 40965
nohup.out:3207:2014-01-22 14:24:00.546 [qtp20266009-2608] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3209:2014-01-22 14:56:02.479 [qtp20266009-2793] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3211:2014-01-22 18:50:50.859 [qtp20266009-2764] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3213:2014-01-22 18:50:50.870 [qtp20266009-2792] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3215:2014-01-22 18:50:50.918 [qtp20266009-2868] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3217:2014-01-22 18:50:50.949 [qtp20266009-2873] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3219:2014-01-22 18:50:50.989 [qtp20266009-2880] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3221:2014-01-22 18:50:51.109 [qtp20266009-2764] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3223:2014-01-22 18:50:51.129 [qtp20266009-2805] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3225:2014-01-22 18:50:51.179 [qtp20266009-2771] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must end with '}' at character 16383
nohup.out:3226:2014-01-22 18:50:51.199 [qtp20266009-2729] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3228:2014-01-22 18:50:51.218 [qtp20266009-2873] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3230:2014-01-22 18:50:51.239 [qtp20266009-2872] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3232:2014-01-22 18:50:51.266 [qtp20266009-2869] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3233:2014-01-22 18:50:51.268 [qtp20266009-2879] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3235:2014-01-22 18:50:51.329 [qtp20266009-2882] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3237:2014-01-22 18:50:51.498 [qtp20266009-2808] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3239:2014-01-22 18:50:51.499 [qtp20266009-2805] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3240:2014-01-22 18:50:51.539 [qtp20266009-2771] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3242:2014-01-22 18:50:51.589 [qtp20266009-2729] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3243:2014-01-22 18:50:51.690 [qtp20266009-2869] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3245:2014-01-22 18:50:51.712 [qtp20266009-2880] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3247:2014-01-22 18:50:51.747 [qtp20266009-2882] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3248:2014-01-22 18:50:51.749 [qtp20266009-2867] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3250:2014-01-22 18:50:51.769 [qtp20266009-2888] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3252:2014-01-22 18:50:59.345 [qtp20266009-2870] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3254:2014-01-22 18:50:59.349 [qtp20266009-2793] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3256:2014-01-22 18:50:59.346 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3258:2014-01-22 18:50:59.483 [qtp20266009-2793] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 20480
nohup.out:3259:2014-01-22 18:50:59.637 [qtp20266009-2764] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3261:2014-01-22 18:50:59.648 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3263:2014-01-22 18:50:59.686 [qtp20266009-2764] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3264:2014-01-22 18:50:59.689 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3266:2014-01-22 18:50:59.709 [qtp20266009-2808] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3268:2014-01-22 18:50:59.814 [qtp20266009-2870] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3269:2014-01-22 18:50:59.897 [qtp20266009-2793] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3270:2014-01-22 18:50:59.898 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3272:2014-01-22 18:50:59.958 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3274:2014-01-22 18:51:00.018 [qtp20266009-2792] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 32768
nohup.out:3275:2014-01-22 18:51:00.117 [qtp20266009-2870] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3276:2014-01-22 18:51:00.549 [qtp20266009-2771] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3278:2014-01-22 18:51:00.658 [qtp20266009-2860] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3280:2014-01-22 18:51:00.660 [qtp20266009-2729] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3281:2014-01-22 18:51:00.662 [qtp20266009-2861] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3282:2014-01-22 18:51:01.807 [qtp20266009-2869] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3283:2014-01-22 18:51:01.808 [qtp20266009-2868] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3285:2014-01-22 18:51:01.828 [qtp20266009-2880] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3287:2014-01-22 18:51:02.078 [qtp20266009-2880] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3289:2014-01-22 18:51:02.080 [qtp20266009-2882] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3290:2014-01-22 18:51:02.165 [qtp20266009-2872] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3291:2014-01-22 18:51:02.166 [qtp20266009-2868] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3292:2014-01-22 18:51:02.245 [qtp20266009-2882] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3294:2014-01-22 18:51:02.829 [qtp20266009-2891] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3295:2014-01-22 18:51:03.648 [qtp20266009-2870] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3297:2014-01-22 18:51:03.668 [qtp20266009-2808] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: A JSONObject text must begin with '{' at character 0
nohup.out:3299:2014-01-22 18:51:03.731 [qtp20266009-2867] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 40960
nohup.out:3301:2014-01-22 18:51:03.732 [qtp20266009-2870] ERROR org.eclipse.orion.server.config - Meta File Error, cannot read JSON file /var/home/adrian/eclipse-orion-ws/ad/adrian/user.json: Unterminated string at character 40960
adrian@tanga:~$

Comment 18 Anthony Hunter

2014-01-22 13:41:02 EST

(In reply to Adrian Aichner from comment #17)
> Can you also explain why I can readily produce a variation of the error by
> running
> 
> Background Operations	Ctrl+Shift+O
> 
> It does not happened until a few operations have accumulated after I
> [Remove Completed]
> operations.

I cannot reproduce single clicking on the remove completed button, but I get the error every time I double click on the remove completed button. So yes same double click a button two simultaneous operations started issue.

Comment 19 Adrian Aichner

2014-01-22 13:48:41 EST

(In reply to Anthony Hunter from comment #18)
> (In reply to Adrian Aichner from comment #17)
> > Can you also explain why I can readily produce a variation of the error by
> > running
> > 
> > Background Operations	Ctrl+Shift+O
> > 
> > It does not happened until a few operations have accumulated after I
> > [Remove Completed]
> > operations.
> 
> I cannot reproduce single clicking on the remove completed button, but I get
> the error every time I double click on the remove completed button. So yes
> same double click a button two simultaneous operations started issue.

But I get these errors of
https://bugs.eclipse.org/bugs/show_bug.cgi?id=423290#c16
when I use keyboard shortcut
Ctrl+Shift+O

Could keydown AND keyup be responsible here?

Anyway we'll see what issues remain once your fix is in place.

Comment 20 Anthony Hunter

2014-01-28 17:10:38 EST

The underlying issue in the case of "A JSONObject text must begin with '{' at character 0" is that one thread is writing an updated metadata file and another thread is trying to read the same metadata file. The read finds an empty file while the write is in progress.

I created a JUnit test in SimpleMetaStoreConcurrencyTests that duplicates the problem by reading and writing properties to the same user.json file in multiple threads.

To solve this issue, I added a ReadWriteLock so that reads are blocked while the user is being updated. There is a lock map that maintains locks per user, so that a lock only locks that userId while it is being written.

The SimpleMetaStoreConcurrencyTests is commit:
http://git.eclipse.org/c/orion/org.eclipse.orion.server.git/commit/?id=cea3c5de5f08ef5a595855b7a1690b017c72e58f

The commit to add the ReadWriteLock to UserInfo create/read/update/delete to the SimpleMetaStore is:
http://git.eclipse.org/c/orion/org.eclipse.orion.server.git/commit/?id=698bac3417aa4ed36b058bc0e586f067db76010e&context=3&ignorews=1&ss=0

ReadWriteLock needs to be also added to the workspace and project metadata after the properties metadata is fixed. I will add a new bug for this issue.

Comment 21 Adrian Aichner

2014-02-12 13:11:19 EST

(In reply to Adrian Aichner from comment #19)
> (In reply to Anthony Hunter from comment #18)
> > (In reply to Adrian Aichner from comment #17)
> > > Can you also explain why I can readily produce a variation of the error by
> > > running
> > > 
> > > Background Operations	Ctrl+Shift+O
> > > 
> > > It does not happened until a few operations have accumulated after I
> > > [Remove Completed]
> > > operations.
> > 
> > I cannot reproduce single clicking on the remove completed button, but I get
> > the error every time I double click on the remove completed button. So yes
> > same double click a button two simultaneous operations started issue.
> 
> But I get these errors of
> https://bugs.eclipse.org/bugs/show_bug.cgi?id=423290#c16
> when I use keyboard shortcut
> Ctrl+Shift+O
> 
> Could keydown AND keyup be responsible here?
> 
> Anyway we'll see what issues remain once your fix is in place.

This looks fully solved now from my end as well.

I can click git fetch 10 times quickly without getting any of these errors.

Also, the previously reliable method Background Operations Ctrl+Shift+O does not causes anything in the logs either.

My last related log entry is from 2014-02-08.