Hundreds of 500-pages out of the blue. All related to database errors ("An error occurred parsing (locally or remotely) the arguments to DATASTORE_V3.Get()")

123 views
Skip to first unread message

Per

unread,
Oct 3, 2012, 4:07:43 PM10/3/12
to google-a...@googlegroups.com

I only realised after posting the other thread (about the response time increase) that we're actually encountering hundreds and hundreds of database errors.

As always, the log file doesn't tell me anything. It's the generic DATASTORE_V3.Get() all over. We didn't make any deployment, we didnd't change any code recently, the load pattern
didn't change, and there is no common trend either. The errors occur for an hour or so, strike everywhere (dozens of different clients are affected) and then the problem disappears
for a few hours.

Here's the stacktrace again (from about 90 minutes ago):

https://www.small-improvements.com/dashboard javax.servlet.ServletException: com.google.apphosting.api.ApiProxy$ArgumentException: An error occurred parsing (locally or remotely) the arguments to DATASTORE_V3.Get(). at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.handle(AppVersionHandlerMap.java:268) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:326) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:923) at com.google.apphosting.runtime.jetty.RpcRequestParser.parseAvailable(RpcRequestParser.java:76) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:146) at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:447) at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:452) at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:459) at com.google.tracing.TraceContext.runInContext(TraceContext.java:701) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:336) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:328) at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:456) at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251) at java.lang.Thread.run(Thread.java:679) Caused by: com.google.apphosting.api.ApiProxy$ArgumentException: An error occurred parsing (locally or remotely) the arguments to DATASTORE_V3.Get(). at com.google.apphosting.runtime.ApiProxyImpl$AsyncApiFuture.success(ApiProxyImpl.java:464) at com.google.apphosting.runtime.ApiProxyImpl$AsyncApiFuture.success(ApiProxyImpl.java:392) at com.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher$1.runInContext(RpcStub.java:781) at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:459) at com.google.tracing.TraceContext.runInContext(TraceContext.java:701) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:336) at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:328) at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:456) at com.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.rpcFinished(RpcStub.java:823) at com.google.net.rpc3.client.RpcStub$RpcCallbackDispatcher.success(RpcStub.java:808) at com.google.net.rpc3.impl.client.RpcClientInternalContext.runCallbacks(RpcClientInternalContext.java:893) at com.google.net.rpc3.impl.client.RpcClientInternalContext.finishRpcAndNotifyApp(RpcClientInternalContext.java:798) at com.google.net.rpc3.impl.client.RpcNetChannel.afterFinishingActiveRpc(RpcNetChannel.java:1063) at com.google.net.rpc3.impl.client.RpcNetChannel.finishRpc(RpcNetChannel.java:911) at com.google.net.rpc3.impl.client.RpcNetChannel.handleResponse(RpcNetChannel.java:2265) at com.google.net.rpc3.impl.client.RpcNetChannel.messageReceived(RpcNetChannel.java:2068) at com.google.net.rpc3.impl.client.RpcNetChannel.access$2000(RpcNetChannel.java:143) at com.google.net.rpc3.impl.client.RpcNetChannel$TransportCallback.receivedMessage(RpcNetChannel.java:3127) at com.google.net.rpc3.impl.client.RpcChannelTransportData$TransportCallback.receivedMessage(RpcChannelTransportData.java:599) at com.google.net.rpc3.impl.wire.RpcBaseTransport.receivedMessage(RpcBaseTransport.java:417) at com.google.apphosting.runtime.udrpc.UdrpcTransport$ClientAdapter.receivedMessage(UdrpcTransport.java:424) at com.google.apphosting.runtime.udrpc.UdrpcTransport.dispatchPacket(UdrpcTransport.java:265) at com.google.apphosting.runtime.udrpc.UdrpcTransport.readPackets(UdrpcTransport.java:217) at com.google.apphosting.runtime.udrpc.UdrpcTransport$1.run(UdrpcTransport.java:81) at com.google.net.eventmanager.AbstractFutureTask$Sync.innerRun(AbstractFutureTask.java:260) at com.google.net.eventmanager.AbstractFutureTask.run(AbstractFutureTask.java:121) at com.google.net.eventmanager.EventManagerImpl.runTask(EventManagerImpl.java:578) at com.google.net.eventmanager.EventManagerImpl.internalRunWorkerLoop(EventManagerImpl.java:1002) at com.google.net.eventmanager.EventManagerImpl.runWorkerLoop(EventManagerImpl.java:884) at com.google.net.eventmanager.WorkerThreadInfo.runWorkerLoop(WorkerThreadInfo.java:136) at com.google.net.eventmanager.EventManagerImpl$WorkerThread.run(EventManagerImpl.java:1855)


And this is the error spike distribution today:





I find it very frustrating that GAE is so inconsistent. We had severe issues two months ago and had to reimburse several clients for downtimes caused by very similar problems. Then it was fine for 2 months,
and just when I go on vacation, it breaks down again. Anything I can do on my end?


Cheers,
Per



Emanuele Ziglioli

unread,
Oct 3, 2012, 9:36:45 PM10/3/12
to google-a...@googlegroups.com
GAE looks down to me:

Dynamic Get: Latency

Measures the latency, in milliseconds, of one round-trip HTTP request to a simple dynamically-served handler.

Uncaught exception from servlet
org.apache.xerces.util.ObjectFactory$ConfigurationError: Provider org.apache.xerces.parsers.StandardParserConfiguration could not be instantiated: com.google.apphosting.api.DeadlineExceededException: This request (ccb0be8e8ff82131) started at 2012/10/04 01:30:10.362 UTC and was still executing at 2012/10/04 01:31:10.042 UTC.
	at org.apache.xerces.util.ObjectFactory.newInstance(ObjectFactory.java:303)
	at org.apache.xerces.util.ObjectFactory.createObject(ObjectFactory.java:224)
	at org.apache.xerces.util.ObjectFactory.createObject(ObjectFactory.java:119)
	at org.apache.xerces.parsers.SAXParser.<init>(SAXParser.java:140)
	at org.apache.xerces.parsers.SAXParser.<init>(SAXParser.java:125)
	at org.apache.xerces.jaxp.SAXParserImpl.<init>(SAXParserImpl.java:102)
	at org.apache.xerces.jaxp.SAXParserFactoryImpl.newSAXParserImpl(SAXParserFactoryImpl.java:112)
	at org.apache.xerces.jaxp.SAXParserFactoryImpl.setFeature(SAXParserFactoryImpl.java:140)
	at org.mortbay.xml.XmlParser.makeFactorySecure(XmlParser.java:162)
	at org.mortbay.xml.XmlParser.setValidating(XmlParser.java:102)
	at org.mortbay.xml.XmlParser.<init>(XmlParser.java:91)
	at org.mortbay.jetty.webapp.TagLibConfiguration.configureWebApp(TagLibConfiguration.java:210)
	at org.mortbay.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1247)
	at org.mortbay.jetty.handler.ContextHandler.doStart(ContextHandler.java:517)
	at org.mortbay.jetty.webapp.WebAppContext.doStart(WebAppContext.java:467)
	at org.mortbay.component.AbstractLifeCycle.start(AbstractLifeCycle.java:50)
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.createHandler(AppVersionHandlerMap.java:219)
	at com.google.apphosting.runtime.jetty.AppVersionHandlerMap.getHandler(AppVersionHandlerMap.java:194)
	at com.google.apphosting.runtime.jetty.JettyServletEngineAdapter.serviceRequest(JettyServletEngineAdapter.java:134)
	at com.google.apphosting.runtime.JavaRuntime$RequestRunnable.run(JavaRuntime.java:447)
	at com.google.tracing.TraceContext$TraceContextRunnable.runInContext(TraceContext.java:452)
	at com.google.tracing.TraceContext$TraceContextRunnable$1.run(TraceContext.java:459)
	at com.google.tracing.TraceContext.runInContext(TraceContext.java:701)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContextNoUnref(TraceContext.java:336)
	at com.google.tracing.TraceContext$AbstractTraceContextCallback.runInInheritedContext(TraceContext.java:328)
	at com.google.tracing.TraceContext$TraceContextRunnable.run(TraceContext.java:456)
	at com.google.apphosting.runtime.ThreadGroupPool$PoolEntry.run(ThreadGroupPool.java:251)
	at java.lang.Thread.run(Thread.java:679)


Takashi Matsuo

unread,
Oct 4, 2012, 3:22:22 AM10/4/12
to google-a...@googlegroups.com
Hi Per,

Sorry, but I'm not able to locate the log you pasted. Can you confirm the actual time(or time period) of the occurrence?
Do you still see the issue? If yes, can you file a production issue on our issue tracker with more details?

-- Takashi


--
You received this message because you are subscribed to the Google Groups "Google App Engine" group.
To view this discussion on the web visit https://groups.google.com/d/msg/google-appengine/-/U9KKQ-WMZ98J.
To post to this group, send email to google-a...@googlegroups.com.
To unsubscribe from this group, send email to google-appengi...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/google-appengine?hl=en.



--
Takashi Matsuo | Developers Advocate | tma...@google.com

Per

unread,
Oct 4, 2012, 5:41:19 AM10/4/12
to google-a...@googlegroups.com

Hi Takashi,

Here is the last request of one of these spikes, just search backwards from there.

59.167.133.100 - - [03/Oct/2012:16:56:02 -0700] "GET / HTTP/1.1" 500 0 "http://small-improvements.com/" "Mozilla/5.0 
(Macintosh; Intel Mac OS X 10_6_7) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4"
"www.small-improvements.com" ms=2463 cpu_ms=2210 exit_code=103 instance=00c61b117ca2c5dd4a6002dd13f39c6296da66

Also, you have my application ID ("small-improvements-hrd"), and I gave you the general time. The log file is full of these errors, as you can see from the screenshot spikes. I have no idea why you wouldn't be able to find these? Does your search tool really yield "no errors"?  Then it must be fundamentally broken. If I run a search I get hundreds of stacktraces.

Of course I also raised a production error too, which has the exact time. I would have sent you a bug tracker ID for my production issue, if your bug tracker had such a thing. Every support system I've worked with in the past 10 years sends IDs in an email receipt. Yours does not. It seems to be GAE policy to keep customers in the dark, and this makes it a lot harder to tell you about issues -- but you do have my application ID and my name, so it shouldn't be hard to retrieve it that way either.

Cheers,
Per

Takashi Matsuo

unread,
Oct 4, 2012, 6:34:20 AM10/4/12
to google-a...@googlegroups.com

Hi Per,

I couldn't find the logs because I searched for 'Error' severity. Sorry about that. Now I can see your warning logs, escalating it to the engineering team.

If you want to have a tracker ID, please use our issue tracker at:

As you say, the 'Report production issue' feature in the admin console lacks a tracking feature, so we're re-thinking about this tool.

-- Takashi


To view this discussion on the web visit https://groups.google.com/d/msg/google-appengine/-/zwEIyb-Sf6oJ.

To post to this group, send email to google-a...@googlegroups.com.
To unsubscribe from this group, send email to google-appengi...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/google-appengine?hl=en.

Takashi Matsuo

unread,
Oct 4, 2012, 7:02:59 AM10/4/12
to google-a...@googlegroups.com

Hi Per,

I have informed this issue to the engineering team. Thanks for the report.
Anyway, it seems that now the error stopped. Can you confirm?

-- Takashi

Per

unread,
Oct 4, 2012, 4:29:34 PM10/4/12
to google-a...@googlegroups.com
Hi Takashi,

you're right, it seems to have stopped now. The response time is still a bit high, so I'm fearing the error could strike again, but at least right now nothing bad is happening.

I'm always searching using 'HTTP/1.1" 500' to identify failed requests, and I ignore the error level. Maybe I have to rework our logging in that regard, sorry if that confused you.

I guess I'll stop using the "raise production error" feature then, I thought it was the preferred way of raising problems these days. Glad to hear it's not! And thanks for passing this on the engineering team :)

Cheers,
Per

Per

unread,
Oct 9, 2012, 6:12:36 AM10/9/12
to google-a...@googlegroups.com

This error has been striking again, and our customers had the impression the site was down for about two hours. Our customers are complaining and I am really unhappy about this too. I've raised an issue on the tracker (http://code.google.com/p/googleappengine/issues/detail?id=8233).

I know that it's impossible to build an error-free system, and I applauded the most recent 1.7.2 release for all the bugfixes it contained. But several hours of database problems, for the fourth time in about one week, is starting to hurt. I'd like to urge you to continue down the path of fixing bugs above all. Reliability and availability are the only concerns I have about App Engine. I'm entirely satisfied with the existing feature set, and happy to integrate external services (e.g. for email sending) when reaching limitations of app engine. But reliability of the core service and database cannot be outsourced, and having to write post mortems (or reimbursing clients that are affected) more than once every few months is not an option.

Cheers,
Per




Reply all
Reply to author
Forward
0 new messages