Go runtime and log timestamps

58 views
Skip to first unread message

Graham Miller

unread,
Nov 1, 2016, 10:09:10 AM11/1/16
to google-ap...@googlegroups.com
We're seeing some strange behavior regarding time in AppEngine this morning.  It appears that calls to time.Now() as well as any child items in the log viewer get a timestamp of the instance start time.  AFAICT, the instance in question started up at about 7:02:52 this morning.  In the attached screenshot you can see that the main log entry for a given request has the correct timestamp (9:54:28), but the child items have 7:02:52.  Furthermore, we call time.Now() in the code and return the timestamp, and that also appears to be giving 7:02:52.  Did something change overnight?

Thanks.

graham

Inline image 1

Ronoaldo José de Lana Pereira

unread,
Nov 1, 2016, 10:53:58 AM11/1/16
to google-ap...@googlegroups.com
I'm affected by this issue as well. This is a major issue because all time-driven data we are producing is stuck in a moment in time. In our case, time.Now() returns the same value as well, and I'm noticing this for the past few hours (~2:30). All code that we have and that currently relies in time-based data is broken.

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsub...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.



--
Ronoaldo Pereira

Adam Tanner

unread,
Nov 1, 2016, 11:14:03 AM11/1/16
to Ronoaldo José de Lana Pereira, google-ap...@googlegroups.com
Did this start after a redeploy or on already running instances?
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengin...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.



--
Ronoaldo Pereira

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengin...@googlegroups.com.

Graham Miller

unread,
Nov 1, 2016, 11:14:51 AM11/1/16
to Adam Tanner, Ronoaldo José de Lana Pereira, google-ap...@googlegroups.com
We haven't done a redeploy for about a week.

graham


On Tue, Nov 1, 2016 at 11:13 AM, 'Adam Tanner' via google-appengine-go <google-ap...@googlegroups.com> wrote:
Did this start after a redeploy or on already running instances?
On Tue, Nov 1, 2016 at 7:53 AM Ronoaldo José de Lana Pereira <rono...@gmail.com> wrote:
I'm affected by this issue as well. This is a major issue because all time-driven data we are producing is stuck in a moment in time. In our case, time.Now() returns the same value as well, and I'm noticing this for the past few hours (~2:30). All code that we have and that currently relies in time-based data is broken.
2016-11-01 12:08 GMT-02:00 Graham Miller <graham...@gmail.com>:
We're seeing some strange behavior regarding time in AppEngine this morning.  It appears that calls to time.Now() as well as any child items in the log viewer get a timestamp of the instance start time.  AFAICT, the instance in question started up at about 7:02:52 this morning.  In the attached screenshot you can see that the main log entry for a given request has the correct timestamp (9:54:28), but the child items have 7:02:52.  Furthermore, we call time.Now() in the code and return the timestamp, and that also appears to be giving 7:02:52.  Did something change overnight?

Thanks.

graham

Inline image 1

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsub...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.
--
Ronoaldo Pereira

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsub...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsub...@googlegroups.com.

Adam Tanner

unread,
Nov 1, 2016, 12:28:49 PM11/1/16
to google-appengine-go
I'm currently working to reproduce this issue. Are either of you still experiencing this?

Graham Miller

unread,
Nov 1, 2016, 12:33:57 PM11/1/16
to Adam Tanner, google-appengine-go
Thanks.  We actually just deployed a new version of our application, and we cannot reproduce the issue on that new version.  The old instance/version is still returning fixed timestamps.

graham


--

Ronoaldo José de Lana Pereira

unread,
Nov 1, 2016, 12:34:46 PM11/1/16
to Graham Miller, Adam Tanner, google-ap...@googlegroups.com
​Our issue seems to be relative to a single instance. Using this query in logs I was able to find that the logs got stuck in time: 

metadata.serviceName="appengine.googleapis.com"
log="appengine.googleapis.com/request_log"
protoPayload.instanceId="00c61b117c3d6f7a0ab5e27063efd32a27480e4d8d2f13ada94f2be43e"

Every entry I could see in the previous query shows the same logging behavior and it seems that this was the single instance for a while in our app. Other logs with warning level shows up some API calls that rely on timestamp for signature purposes to be affected as well, and an alerting system we have made also uses time.Now() in the subject line. Repeated emails reached with the same timestamp. So I can confirm the instance got stuck in time and time.Now() returned the same date. The offending instance is this one:

Imagem inline 1

This is the only instance we have now and it was started at Nov 1, 2016 9:32:18 AM GMT-3, logs display the same time-stamp in the log entries for every request: 11:47:08.737 GMT-3.

Deleting that auto-scaled instance immediately started a fresh one without the issues reported. To me, seems that the problem got fixed.

I'll be keeping an eye if this still is the case for other instances, but hope the data here can help diagnose the root cause.

Please PM me if you need more details about the project in question, I have logs exported to BigQuery so I can export the relevant bits from them.

Best,


2016-11-01 13:14 GMT-02:00 Graham Miller <graham...@gmail.com>:
We haven't done a redeploy for about a week.

graham

On Tue, Nov 1, 2016 at 11:13 AM, 'Adam Tanner' via google-appengine-go <google-appengine-go@googlegroups.com> wrote:
Did this start after a redeploy or on already running instances?
On Tue, Nov 1, 2016 at 7:53 AM Ronoaldo José de Lana Pereira <rono...@gmail.com> wrote:
I'm affected by this issue as well. This is a major issue because all time-driven data we are producing is stuck in a moment in time. In our case, time.Now() returns the same value as well, and I'm noticing this for the past few hours (~2:30). All code that we have and that currently relies in time-based data is broken.
2016-11-01 12:08 GMT-02:00 Graham Miller <graham...@gmail.com>:
We're seeing some strange behavior regarding time in AppEngine this morning.  It appears that calls to time.Now() as well as any child items in the log viewer get a timestamp of the instance start time.  AFAICT, the instance in question started up at about 7:02:52 this morning.  In the attached screenshot you can see that the main log entry for a given request has the correct timestamp (9:54:28), but the child items have 7:02:52.  Furthermore, we call time.Now() in the code and return the timestamp, and that also appears to be giving 7:02:52.  Did something change overnight?

Thanks.

graham

Inline image 1

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsubscribe...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.
--
Ronoaldo Pereira

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsubscribe...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "google-appengine-go" group.
To unsubscribe from this group and stop receiving emails from it, send an email to google-appengine-go+unsubscribe...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.




--
Ronoaldo Pereira
Reply all
Reply to author
Forward
0 new messages