1110010 - Assertion failure: timestamp <= PR_Now(), at ../../../gecko/dom/quota/QuotaManager.cpp:2379

Status: RESOLVED WONTFIX

(Core :: Storage: IndexedDB, defect)

Description

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

I met this on Flame
Sometimes I reboot the phone, and this assert happens, and then it keeps happening all the time . The only way to fix this is to 'make reset-gaia'


commit 437abd21eec991a1fd8d0ac8ee85bde4749e3a71
Merge: 77ed5bc 3a35ba7
Author: Ryan VanderMeulen <[e-mail]>
Date:   Wed Dec 10 16:01:20 2014 -0500

    Merge inbound to m-c. a=merge
    CLOSED TREE

Comment 1

[Jan Varga [:janv]]

Hm, there's must be a problem with system clock or something.
Ben, can we just remove this assertion ?

Comment 2

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Well, are you sure that nothing else breaks in the quota manager if the system time is artificially set back?

Comment 3

[Jan Varga [:janv]]

I believe this problem will disappear, once a fix for bug 1110585 lands.

Comment 4

[Jan Varga [:janv]]

This should be now fixed.

Comment 5

[Gregor Wagner [:gwagner]]

I am still seeing this issue with current trunk.

Comment 6

[Gregor Wagner [:gwagner]]

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 8734.8781]
0xb4ef465e in mozilla::dom::quota::QuotaManager::EnsureOriginIsInitialized (this=this@entry=0xaf8e6d80, aPersistenceType=aPersistenceType@entry=mozilla::dom::quota::PERSISTENCE_TYPE_PERSISTENT, aGroup=..., aOrigin=..., aIsApp=aIsApp@entry=false, 
    aHasUnlimStoragePerm=aHasUnlimStoragePerm@entry=false, aDirectory=0xafbff988) at ../../../dom/quota/QuotaManager.cpp:2379
2379	      MOZ_ASSERT(timestamp <= PR_Now());
(gdb) bt
#0  0xb4ef465e in mozilla::dom::quota::QuotaManager::EnsureOriginIsInitialized (this=this@entry=0xaf8e6d80, aPersistenceType=aPersistenceType@entry=mozilla::dom::quota::PERSISTENCE_TYPE_PERSISTENT, aGroup=..., aOrigin=..., aIsApp=aIsApp@entry=false, 
    aHasUnlimStoragePerm=aHasUnlimStoragePerm@entry=false, aDirectory=0xafbff988) at ../../../dom/quota/QuotaManager.cpp:2379
#1  0xb4f91818 in mozilla::dom::indexedDB::(anonymous namespace)::OpenDatabaseOp::DoDatabaseWork (this=0xb12027a0) at ../../../dom/indexedDB/ActorsParent.cpp:11293
#2  0xb4f85eea in mozilla::dom::indexedDB::(anonymous namespace)::FactoryOp::Run (this=0xb12027a0) at ../../../dom/indexedDB/ActorsParent.cpp:11137
#3  0xb4336798 in nsThread::ProcessNextEvent (this=0xafa8ef50, aMayWait=<optimized out>, aResult=0xafbffcf7) at ../../../xpcom/threads/nsThread.cpp:855
#4  0xb434af3c in NS_ProcessNextEvent (aThread=0xafa8ef50, aMayWait=aMayWait@entry=false) at /Volumes/2mac/moz/ib2g/xpcom/glue/nsThreadUtils.cpp:265
#5  0xb44ff670 in mozilla::ipc::MessagePumpForNonMainThreads::Run (this=0xafa03340, aDelegate=0xaf8696a0) at ../../../ipc/glue/MessagePump.cpp:339
#6  0xb44ec100 in MessageLoop::RunInternal (this=this@entry=0xaf8696a0) at ../../../ipc/chromium/src/base/message_loop.cc:233
#7  0xb44ec11a in RunHandler (this=0xaf8696a0) at ../../../ipc/chromium/src/base/message_loop.cc:226
#8  MessageLoop::Run (this=this@entry=0xaf8696a0) at ../../../ipc/chromium/src/base/message_loop.cc:200
#9  0xb4337404 in nsThread::ThreadFunc (aArg=0xafa8ef50) at ../../../xpcom/threads/nsThread.cpp:356
#10 0xb69948e8 in _pt_root (arg=0xaf617280) at ../../../../../nsprpub/pr/src/pthreads/ptthread.c:212
#11 0xb6e8c22c in __thread_entry (func=0xb6994841 <_pt_root>, arg=0xaf617280, tls=0xafbffdd0) at bionic/libc/bionic/pthread_create.cpp:105
#12 0xb6e8c3c4 in pthread_create (thread_out=0xbe8613a4, attr=<optimized out>, start_routine=0xb6994841 <_pt_root>, arg=0x78) at bionic/libc/bionic/pthread_create.cpp:224
#13 0x00000000 in ?? ()

Comment 7

[Kartikaya Gupta (email:[e-mail])]

I ran into this too, but at QuotaManager.cpp:2326

Comment 8

[Botond Ballo [:botond]]

I see the assertion at line 2379. I worked around it in my local build by commenting it out.

Comment 9

[Gregor Wagner [:gwagner]]

Jan, can you take a look again?

Comment 10

[Jan Varga [:janv]]

Gregor, do you think it's possible that the system clock on the device is sometimes set back ?

Comment 11

[Gregor Wagner [:gwagner]]

(In reply to Jan Varga [:janv] from comment #10)
> Gregor, do you think it's possible that the system clock on the device is
> sometimes set back ?

yeah thats possible during startup.

Comment 12

[Andrew Overholt [:overholt]]

ISTR the Tarako having issues being reset to the epoch if the battery runs out.  Is this still an issue?

Comment 13

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Making this a warning is a bad idea. At startup we read through the storage directory and determine the oldest temporary data. Later, when using the phone, if we need more space, we will toss out the oldest data. So if we have a bug where we incorrectly determine which data is oldest we may toss out data that is very relevant instead.

So apparently this time bug is a known issue of sorts: the linux time is just wrong at startup for some unknown period and then it magically becomes correct later. I talked with mwu and he explained that there's a time device on the phone that knows the real time, and there's some process at startup where this hardware informs linux of the correct time. Until that happens linux (and Gecko) think it's 1970. We need to figure out why we're not getting the correct time sooner, or figure out some way to block until the time can be queried accurately.

Gregor, who can dive in here? Maybe dhylands?

Comment 14

[Gregor Wagner [:gwagner]]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #13)
> Making this a warning is a bad idea. At startup we read through the storage
> directory and determine the oldest temporary data. Later, when using the
> phone, if we need more space, we will toss out the oldest data. So if we
> have a bug where we incorrectly determine which data is oldest we may toss
> out data that is very relevant instead.
> 
> So apparently this time bug is a known issue of sorts: the linux time is
> just wrong at startup for some unknown period and then it magically becomes
> correct later. I talked with mwu and he explained that there's a time device
> on the phone that knows the real time, and there's some process at startup
> where this hardware informs linux of the correct time. Until that happens
> linux (and Gecko) think it's 1970. We need to figure out why we're not
> getting the correct time sooner, or figure out some way to block until the
> time can be queried accurately.
> 
> Gregor, who can dive in here? Maybe dhylands?

Sounds like a serious issue that can lead to data loss. Adding Hema to see if dave or mike has some cycles for investigation.

Comment 15

[Dave Hylands [:dhylands]]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #13)
> Making this a warning is a bad idea. At startup we read through the storage
> directory and determine the oldest temporary data. Later, when using the
> phone, if we need more space, we will toss out the oldest data. So if we
> have a bug where we incorrectly determine which data is oldest we may toss
> out data that is very relevant instead.
> 
> So apparently this time bug is a known issue of sorts: the linux time is
> just wrong at startup for some unknown period and then it magically becomes
> correct later. I talked with mwu and he explained that there's a time device
> on the phone that knows the real time, and there's some process at startup
> where this hardware informs linux of the correct time. Until that happens
> linux (and Gecko) think it's 1970. We need to figure out why we're not
> getting the correct time sooner, or figure out some way to block until the
> time can be queried accurately.
> 
> Gregor, who can dive in here? Maybe dhylands?

We shouldn't be using wall time to determine the oldest file - that's just wrong - even if the RTC is working properly.

We should be using sometime of monotonic incrementing number.

Comment 16

[Jan Varga [:janv]]

(In reply to Dave Hylands [:dhylands] from comment #15)
> 
> We shouldn't be using wall time to determine the oldest file - that's just
> wrong - even if the RTC is working properly.
> 
> We should be using sometime of monotonic incrementing number.

oh man, another storage directory upgrade :(

Comment 17

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Dave Hylands [:dhylands] from comment #15)
> We should be using sometime of monotonic incrementing number.

Do we have such a thing?

Comment 18

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #17)

Well, regardless, we need a functioning clock :) This is causing troubles beyond this quota issue.

Comment 19

[Dave Hylands [:dhylands]]

The last I heard the RTC issue was caused by some CAF utility which needs to be relinked against the latest XUL or something, but I've only been following the issue peripherally, so I'm not 100% sure.

It seem like the RTC functionality is implemented by the modem code, rather than the kernel.

Comment 20

[Hema Koka [:hema]]

Andrew will help investigate this issue. Dave and Mike are pulled into something else.  

Thanks
Hema

Comment 21

[Michael Vines [:m1] [:evilmachines]]

(In reply to Dave Hylands [:dhylands] from comment #19)
> The last I heard the RTC issue was caused by some CAF utility which needs to
> be relinked against the latest XUL or something, but I've only been
> following the issue peripherally, so I'm not 100% sure.
> 
> It seem like the RTC functionality is implemented by the modem code, rather
> than the kernel.

Please refer to time_genoff.h [1].  On 'system-clock-change', a component is needed to set the new user time via time_genoff_operation({ATS_USER, ..., ...,T_SET}).

Here's an example that I found of code that does something close to what's missing in Gecko: https://gitorious.org/cyandreamproject/android_frameworks_base/commit/d13ad5e20c2d71d08430f3501dd4ef53a22f5fb0

[1] https://www.codeaurora.org/cgit/quic/la/platform/vendor/qcom-opensource/time-services/tree/time_genoff.h?h=LA.BR64.1.1

Comment 22

[Gabriele Svelto [:gsvelto] (PTO)]

CC'ing me and Alexandre since we spent a disproportionate amount of time trying to debug this. I hope I'll have time to look into comment 21 next week because this has bugged me for far too long.

Comment 23

[:gerard-majax]

Brain dump from a former discussion on IRC with mwu:
 - recent platform do not have a rtc, and this is handled by a daemon on the system
 - gecko can save the clock when it receives a value (system-clock-change) via the time-service xpcom component
 - however, during startup, clock will skew
 - this seems to be because gecko will start when time-daemon has not yet re-synced the clock from the saved value

So, if we have code as in comment 21, and if we make sure Gecko is started after time-daemon did its job, that may be a solution.

Comment 24

[Andrew Osmond [:aosmond] (he/him)]

(In reply to Alexandre LISSY :gerard-majax from comment #23)
> Brain dump from a former discussion on IRC with mwu:
>  - recent platform do not have a rtc, and this is handled by a daemon on the
> system
>  - gecko can save the clock when it receives a value (system-clock-change)
> via the time-service xpcom component
>  - however, during startup, clock will skew
>  - this seems to be because gecko will start when time-daemon has not yet
> re-synced the clock from the saved value
> 
> So, if we have code as in comment 21, and if we make sure Gecko is started
> after time-daemon did its job, that may be a solution.

Thanks (and to m1 above), I will try this out and post a patch today if I can get it working.

Comment 25

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Part 1. Add time-services to flame-kk manifest.

Comment 26

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Part 2. Add libtime_genoff to linkable libraries for libxul

Comment 27

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Part 3. Implement Gonk HAL wrapper.

Comment 28

[Andrew Osmond [:aosmond] (he/him)]

mvines: In order to ensure time_daemon is already started, I was considering writing a wrapper around inotify (or getting the inotifywait tool working on flame) to block in b2g.sh on the creation of the socket, since the service should generally speaking be up before us. What is the path? @time_genoff seems to be it but I would like to confirm that and if you are aware of some other more official method? (None seems to be provided by the library.)

Comment 29

[Michael Wu [:mwu]]

(In reply to Andrew Osmond [:aosmond] from comment #28)
> mvines: In order to ensure time_daemon is already started, I was considering
> writing a wrapper around inotify (or getting the inotifywait tool working on
> flame) to block in b2g.sh on the creation of the socket, since the service
> should generally speaking be up before us. What is the path? @time_genoff
> seems to be it but I would like to confirm that and if you are aware of some
> other more official method? (None seems to be provided by the library.)

init already provides a way to query if a service is up. Try checking the init.svc.time_daemon property.

Comment 30

[:gerard-majax]

May I ask a dumb question regarding time_genoff ? What is the expected behavior, at reboot, after the device was properly shut down and the clock synced correctly as suggested in comment 21 ?

Should we see:
 1. at boot, before time_daemon starts, system date around 1970's
 2. at boot, after time_daemon did its job, system date back to the value it was when the device was shut down
 3. once gecko runs and network is connected, system time is properly synced

Comment 31

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Implement XPCOM component to capture clock changes for QC time daemon

mwu: I did not leave in checking to see if the service was running in the end, because I don't think that is why we have been not configuring the service as expected in all cases.

If you consider the changes in the patch, in addition to reviewing [1], you will notice that system-clock-change is only sent to its observers *if and only if* there was previously a window listener for moztimechange. The first system-clock-change from my testing is always generated (after a reboot) before a proper window listener is added, and so the system-clock-change event for the XPCOM components is actually dropped.

Another thing to consider is I modeled QTimeService to update time_daemon with the current system time. This is consistent with the code reference mvines provided in comment 21 (as it samples the system clock for the adjustment for both libtime_genoff and ANDROID_ALARM_SET_RTC). However it appears that the original QC XPCOM component sets it to a slightly different time; I believe this is relative to the existing value in time_daemon. I'm not sure which is the correct behaviour precisely. mvines?

[1] https://dxr.mozilla.org/mozilla-central/source/dom/events/EventListenerManager.cpp#316

Comment 32

[Michael Wu [:mwu]]

Not sure I know what's going on well enough to answer your questions here..

Comment 33

[Alin Jerpelea]

time_daemon blob can be replaced with an open source implementation

https://github.com/sonyxperiadev/timekeep

Comment 34

[Kai-Chih Hu [:khu]]

+'ed because of bug 1061797.

Comment 36

[Mark Banner (:standard8)]

(In reply to Michael Wu [:mwu] from comment #32)
> Not sure I know what's going on well enough to answer your questions here..

Any idea of who to ask? or can you cancel the feedback request to signal that you're not going to be giving feedback?

Comment 37

[howie [:howie]]

Hi Ben, do you have any feedback for the patch?

Comment 38

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 8568552 [details] [diff] [review]
Implement XPCOM component to capture clock changes for QC time daemon

Fabrice will look at the js, I'll look at the c++, and we'll see what happens!

Comment 39

[Gregor Wagner [:gwagner]]

I applied the patch and still see F/MOZ_Assert( 1504): Assertion failure: timestamp <= PR_Now(), at ../../../dom/quota/QuotaManager.cpp:2331

Comment 40

[:gerard-majax]

FYI I'm stealing bits of this (the time observers changes) and working on supporting the free dropin replacement that is timekeep in bug 1146900.

Comment 41

[:gerard-majax]

And timekeep does work quite well on my Flame also.

Comment 42

[No-Jun Park [:njpark]]

Just to note that when loading the latest *debug* build, the phone fails restart, and the logcat keeps sending out this MOZ_ASSERT line while showing blank screen. so with the debug build, I can't reboot the phone at all atm.

F/MOZ_Assert( 3680): Assertion failure: timestamp <= PR_Now(), at ../../../gecko/dom/quota/QuotaManager.cpp:2319

This does not happen with the eng build though.

Version Used:

Build ID               20150402073148
Gaia Revision          f37be8b44cb7c3a147b9615ab76743b760f08eeb
Gaia Date              2015-04-02 02:53:36
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/35046df9df1f
Gecko Version          40.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150402.110149
Firmware Date          Thu Apr  2 11:01:58 EDT 2015
Bootloader             L1TC000118D0

Comment 43

[:gerard-majax]

Andrew, do you have time for updating this ? The observer part of bug 1146900 should land very soon, if you are too busy I can take this bug and update everything and land it.

Comment 44

[:gerard-majax]

Stealing to update

Comment 45

[:gerard-majax]

We will need attachment 8582996 [details] [diff] [review] from 1146900

Comment 46

[:gerard-majax]

Attachment: Implement XPCOM component to capture clock changes for QC time daemon

Comment 47

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #45)
> We will need attachment 8582996 [details] [diff] [review] from 1146900

On my system, I don't have any problem without this patch, just for the record.

Comment 48

[:gerard-majax]

Comment on attachment 8589640 [details] [diff] [review]
Implement XPCOM component to capture clock changes for QC time daemon

That's indeed the exact same patch as the one provided by Andrew, with just changes because package-manifest.in and moz.build have moved on in between.

Comment 49

[:gerard-majax]

Attachment: Device PR

This blob become useless once we have QTimeService.

Comment 50

[:gerard-majax]

I'm checking whether we may also need the same timeservice detection for timekeep users.

Comment 51

[:gerard-majax]

Attachment: Implement XPCOM component to capture clock changes for QC time daemon

Comment 52

[:gerard-majax]

I've hacked my non eng build with:
> diff --git a/dom/quota/QuotaManager.cpp b/dom/quota/QuotaManager.cpp
> index ff1dfe9..1ab33a7 100644
> --- a/dom/quota/QuotaManager.cpp
> +++ b/dom/quota/QuotaManager.cpp
> @@ -2316,6 +2316,11 @@ QuotaManager::EnsureOriginIsInitialized(PersistenceType aPersistenceType,
>  
>        timestamp = ts;
>  
> +      if (timestamp <= PR_Now()) {
> +        printf_stderr("MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=%lld PR_Now()=%lld\n", timestamp, PR_Now());
> +        MOZ_CRASH("Failure on (timestamp <= PR_Now())");
> +      }
> +
>        MOZ_ASSERT(timestamp <= PR_Now());
>      }
>

That is on a Z3 Compact with TimeKeep enabled: Gecko does start with a quite good system date.

Yet, it looks like I do hit the crash consistently, with those logs being available:
> $ adb logcat -v threadtime | grep ASSERT
> 04-09 15:38:21.120  6101  6200 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586701132123
> 04-09 15:38:27.610  6205  6293 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586707615163
> 04-09 15:38:34.930  6306  6413 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586714941263
> 04-09 15:38:41.930  6418  6521 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586721938474
> 04-09 15:38:48.460  6528  6624 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586728464369

If I just print those values without the MOZ_CRASH call, I get something similar:
> 04-09 15:41:49.120  9190  9277 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=0 PR_Now()=1428586909124301
> 04-09 15:41:56.030  9190  9277 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1417187715000 PR_Now()=1428586916033865
> 04-09 15:42:06.220  9190  9277 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1427467523866046 PR_Now()=1428586926226420
> 04-09 15:42:06.560  9190  9277 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1417179772000 PR_Now()=1428586926569693

At that point, my Gaia shows lockscreen and is totally usable ...

Comment 53

[:gerard-majax]

So, in comment 52, I had some values. Those are coming from an old profile, so it may not be conclusive.

Meanwhile, a fresh profile still exhibits this:
> 04-09 16:19:46.877 12706 12803 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428588426415134 PR_Now()=1428589186894625
> 04-09 16:19:46.877 12706 12803 I Gecko   : MOZ_ASSERT() for aOrigin=chrome delta=-760479491
> 04-09 16:19:50.237 12706 12803 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428588431162745 PR_Now()=1428589190247195
> 04-09 16:19:50.237 12706 12803 I Gecko   : MOZ_ASSERT() for aOrigin=1029+f+app://system.gaiamobile.org delta=-759084450
> 04-09 16:19:59.017 12706 12803 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428588444053226 PR_Now()=1428589199034547
> 04-09 16:19:59.017 12706 12803 I Gecko   : MOZ_ASSERT() for aOrigin=1030+f+app://verticalhome.gaiamobile.org delta=-754981321
> 04-09 16:19:59.707 12706 12803 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428588441207761 PR_Now()=1428589199723581
> 04-09 16:19:59.707 12706 12803 I Gecko   : MOZ_ASSERT() for aOrigin=1019+f+app://keyboard.gaiamobile.org delta=-758515820

Device clock was good, the issue only happens after booting a second time.
STR were:
 0. adb shell stop b2g;
 1. Make sure system clock is correct
 2. adb shell rm -r /data/b2g /data/local
 3. adb shell start b2g
 4. Complete FTU
 5. adb shell stop b2g
 6. adb shell start b2g

Expected:
 No MOZ_ASSERT() being hit

Actual:
 MOZ_ASSERT will get hit

Comment 54

[:gerard-majax]

Attachment: Patch used to reproduce MOZ_ASSERT

Comment 55

[:gerard-majax]

Creating the new profile:
04-09 16:37:58.557 13134 13134 I Gecko   : -*- TimeKeepService: B2G time service enabled
04-09 16:38:02.797 13134 13215 I Gecko   : MOZ_ASSERT() created for aOrigin=chrome timestamp=1428590282812790
04-09 16:38:07.997 13134 13215 I Gecko   : MOZ_ASSERT() created for aOrigin=1029+f+app://system.gaiamobile.org timestamp=1428590288009376
04-09 16:38:18.367 13134 13215 I Gecko   : MOZ_ASSERT() created for aOrigin=1019+f+app://keyboard.gaiamobile.org timestamp=1428590298384141
04-09 16:38:21.307 13134 13215 I Gecko   : MOZ_ASSERT() created for aOrigin=1030+f+app://verticalhome.gaiamobile.org timestamp=1428590301316469

Restarting Gecko with this profile:
04-09 16:39:20.457 13717 13717 I Gecko   : -*- TimeKeepService: B2G time service enabled
04-09 16:39:25.257 13717 13805 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428590282812790 PR_Now()=1428590365265806
04-09 16:39:25.257 13717 13805 I Gecko   : MOZ_ASSERT() for aOrigin=chrome delta=-82453016
04-09 16:39:28.057 13717 13805 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428590288009376 PR_Now()=1428590368072469
04-09 16:39:28.057 13717 13805 I Gecko   : MOZ_ASSERT() for aOrigin=1029+f+app://system.gaiamobile.org delta=-80063093
04-09 16:39:35.797 13717 13805 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428590301316469 PR_Now()=1428590375814779
04-09 16:39:35.797 13717 13805 I Gecko   : MOZ_ASSERT() for aOrigin=1030+f+app://verticalhome.gaiamobile.org delta=-74498310
04-09 16:39:36.197 13717 13805 I Gecko   : MOZ_ASSERT(timestamp <= PR_Now() |=> timestamp=1428590298384141 PR_Now()=1428590376207419
04-09 16:39:36.197 13717 13805 I Gecko   : MOZ_ASSERT() for aOrigin=1019+f+app://keyboard.gaiamobile.org delta=-77823278

Comment 56

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Jan, isn't this the milliseconds vs. microseconds problem?

Comment 57

[:gerard-majax]

Sorry, my STR in comment 53 were wrong regarding MOZ_ASSERT() behavior. Indeed, I can only reproduce the issue if:
 - I create a new profile with system date being set a X
 - stop b2g, get system date backward, X-y
 - start b2g

Then timestamp value read is in the future compared to the current time reported by PR_Now().

Comment 58

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Yeah, those steps are guaranteed to trip this assertion. Jan, we should figure out how to handle this case.

Comment 59

[:gerard-majax]

Gregor suggested this might be related to timezones: he started the device with New York timezone and later changed it to Los Angeles, before rebooting.

Comment 60

[Gregor Wagner [:gwagner]]

(In reply to Alexandre LISSY :gerard-majax from comment #59)
> Gregor suggested this might be related to timezones: he started the device
> with New York timezone and later changed it to Los Angeles, before rebooting.

I dont do it all the time and still get the assertion but it could be related since the time might adjust according to the time zone in the background.

Comment 61

[Andrew Osmond [:aosmond] (he/him)]

Attachment: Implement XPCOM component to capture clock changes for QC time daemon, v2

Change component to register with the native time service to ensure observers get the desired notifications.

Comment 62

[:gerard-majax]

So I tried several runs of flashing, booting, etc., on a debug flame build, and I was never able to hit the issue with my fixed xpcom time service. I don't see a good reason, with this landed, that one would be able to get a profile running with backward time as long as Gecko is able to start after time_daemon (timekeep on devices using it) has set the proper clock time.

The logcat provided to me by Andrew that reproduced this issue explicitely shows that Gecko gets started prior time_daemon could restore a proper clock ; indeed I suspect it restored nothing proper at all.

Comment 63

[Gregor Wagner [:gwagner]]

Still seeing:
I/Gecko   (  208): MOZ_ASSERT() for aOrigin=19+f+app://keyboard.gaiamobile.org delta=7942649
I/Gecko   (  208): MOZ_ASSERT(timestamp > PR_Now() |=> timestamp=1428626567534668 PR_Now()=1428626559592019
F/MOZ_Assert(  208): Assertion failure: timestamp <= PR_Now(), at ../../../dom/quota/QuotaManager.cpp:2328
F/libc    (  208): Fatal signal 11 (SIGSEGV) at 0x00000000 (code=1), thread 1133 (Storage I/O)

Comment 64

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Ah, bug 1110585 fixed the scale conversions...

Comment 65

[:gerard-majax]

(In reply to Gregor Wagner [:gwagner] from comment #63)
> Still seeing:
> I/Gecko   (  208): MOZ_ASSERT() for
> aOrigin=19+f+app://keyboard.gaiamobile.org delta=7942649
> I/Gecko   (  208): MOZ_ASSERT(timestamp > PR_Now() |=>
> timestamp=1428626567534668 PR_Now()=1428626559592019
> F/MOZ_Assert(  208): Assertion failure: timestamp <= PR_Now(), at
> ../../../dom/quota/QuotaManager.cpp:2328
> F/libc    (  208): Fatal signal 11 (SIGSEGV) at 0x00000000 (code=1), thread
> 1133 (Storage I/O)

Thanks, we do see a slight discrepency in time indeed. I really need full |adb logcat -v threadtime| from the very first start to hitting the issue, to check the behavior of the system clock.

Comment 66

[:gerard-majax]

Andrew, if your gMozTimeService.register() is the valid fix, we will also need on the timekeep xpcom component https://github.com/mozilla-b2g/device-shinano-common/tree/master/timekeep-service

Comment 67

[:gerard-majax]

So I had a look at Gregor's latest logs. The MOZ_ASSERT() condition that crashes is on the system app. The first log was produced during the first boot of the device, while the second log was gathered after rebooting. We would then expect that the system clock when Gecko starts in the second case is *after* the system clock when Gecko was shutdown in the first case.

We can see, from the first log:
> 04-10 14:18:31.530  1322  1385 I Gecko   : MOZ_ASSERT() created for aOrigin=1029+f+app://system.gaiamobile.org timestamp=1428689911545798

And from the second log:
> 04-10 14:18:31.030   210   885 I Gecko   : MOZ_ASSERT() for aOrigin=1029+f+app://system.gaiamobile.org delta=499285

So the timestamps shows that it makes sense to crash, since the condition is not met.

Looking further, the first log shows:
> 06-10 18:22:15.869   322   322 I rmt_storage: rmt_storage_disconnect_cb: clnt_h=0x0x6 conn_h=0x0xb729c178
> 04-10 14:18:22.000  1322  1322 W GeckoConsole: [JavaScript Error: "Settings queue head blocked at {83b41996-f2c8-42ed-8329-88a0cde9732b} for 26250966.13 secs, Settings API may be soft lockup. Lock from: SettingsServiceLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:80:17

So the clock gets synced at "04-10 14:18:22.000", on the first boot.

During the second boot, we see:
> 06-10 18:25:01.339   204   555 E AudioFlinger: no wake lock to update!
> 04-10 14:18:22.000   210   210 W GeckoConsole: [JavaScript Error: "Settings queue head blocked at {1a1b3f91-f75a-4013-aba5-0e6c61b0d750} for 26250800.599 secs, Settings API may be soft lockup. Lock from: SettingsServiceLock@jar:file:///system/b2g/omni.ja!/components/SettingsService.js:80:17

So we resurrect the device with the *same* time. Given that on the second boot we have less IO (files for the profile are already created), it may easily explain why we reach the quota manager earlier and hence at a wrong time.

This leads me to some questions:
 - should we also sync the clock at shutdown time ?
 - is it expected that we restore the same clock on the next boot ? And hence, it may be the answer to Andrew's question in comment 31: "However it appears that the original QC XPCOM component sets it to a slightly different time; I believe this is relative to the existing value in time_daemon. I'm not sure which is the correct behaviour precisely."

Comment 68

[:gerard-majax]

Attachment: Tracking time update against the system

This grep shows that in my case, I see the system time being updated by the XPCOM component. That do not happens in Gregor's case (no line with "QC-time-services: Daemon: write into file").

With this, my device clearly do not show the behavior described earlier, i.e., on the second boot it properly restore the *current expected* time.

Gregor, did you had Wi-Fi and/or a SIM card with network ?

Comment 69

[[:fabrice] Fabrice Desré]

Comment on attachment 8590343 [details] [diff] [review]
Implement XPCOM component to capture clock changes for QC time daemon, v2

Review of attachment 8590343 [details] [diff] [review]:
-----------------------------------------------------------------

Gregor, do you mind reviewing that? It seems you are much more aware of the topic than I am.

Comment 70

[:gerard-majax]

Michael, is it expected that we have the device restoring the very same clock between two reboots ?

Comment 71

[Gregor Wagner [:gwagner]]

Comment on attachment 8590343 [details] [diff] [review]
Implement XPCOM component to capture clock changes for QC time daemon, v2

Review of attachment 8590343 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/system/gonk/QTimeService.js
@@ +62,5 @@
> +  /* Don't conflict with the vendor service if it is installed. */
> +  let qts = null; // Qualcomm Time Service
> +  try {
> +    qts = Cc['@qti.qualcomm.com/timeservice;1'].getService(Ci.nsIObserver);
> +  } catch(e) {

Should we log a warning here?

@@ +68,5 @@
> +
> +  let tks = null; // TimeKeep Service
> +  try {
> +    tks = Cc['@mozilla.org/timekeep-service;1'].getService(Ci.nsIObserver);
> +  } catch(e) {

Same here.

@@ +91,5 @@
> +  classInfo: XPCOMUtils.generateCI({
> +    classID: QTIMESERVICE_CID,
> +    contractID: QTIMESERVICE_CONTRACTID,
> +    interfaces: [Ci.nsIObserver],
> +    classDescription: "B2G Qualcomm Time Service",

Can you do a search and replacement for Qualcomm with Q

Comment 72

[Michael Wu [:mwu]]

This component needs to land in a device repo since it is specific to CAF based devices. PRODUCT_COPY_FILES will do the trick.

Comment 73

[:gerard-majax]

Reproduced on David's device, looks like reset-gaia on a debug build helps :)

Comment 74

[:gerard-majax]

Attachment: clock_david_firstboot.log

First boot on David's device. We can see that clock gets properly synced:

> clock_david_firstboot.log:04-17 16:27:08.078   213   213 I Gecko   : timeservice.js deltaMs=2582762
> clock_david_firstboot.log:04-17 16:27:08.078   213   213 I Gecko   : timeservice.js Settime=1401666366622
> clock_david_firstboot.log:04-17 16:27:08.078   213   213 D QC-time-services: Lib:time_genoff_operation: pargs->base = 2
> clock_david_firstboot.log:04-17 16:27:08.078   213   213 D QC-time-services: Lib:time_genoff_operation: pargs->operation = 0
> clock_david_firstboot.log:04-17 16:27:08.078   213   213 D QC-time-services: Lib:time_genoff_operation: pargs->ts_val = 1401666366622
> clock_david_firstboot.log:04-17 16:27:08.078   213   213 D QC-time-services: Lib:time_genoff_operation: Send to server  passed!!
> clock_david_firstboot.log:04-17 16:27:08.078   265   562 E QC-time-services: Daemon: Time-services: Waiting to acceptconnection
> clock_david_firstboot.log:04-17 16:27:08.078   265   562 D QC-time-services: Daemon: Connection accepted:time_genoff
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:Received base = 2, unit = 1, operation = 0,value = 1401666366622
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:genoff_opr: Base = 2, val = 1401666366622, operation = 0
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:rtc_get: Time read from RTC -- MM/DD/YY HH:MM:SS0/1/70 23:2:50
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:Value read from RTC seconds = 82970000
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:new time 1401666366622 
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon: delta 1401583396622 genoff 1401583396622 
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:genoff_persistent_update: Writing genoff = 1401583396622 to memory
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:Opening File: /data/time/ats_2
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon:time_persistent_memory_opr:Genoff write operation 
> clock_david_firstboot.log:04-17 16:27:08.088   265  1236 D QC-time-services: Daemon: write into file 1401583396 time 02:43:16 06/01/2014
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Updating the TOD offset
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon:genoff_persistent_update: Writing genoff = 1401583396622 to memory
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon:Opening File: /data/time/ats_1
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon:time_persistent_memory_opr:Genoff write operation 
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon: write into file 1401583396 time 02:43:16 06/01/2014
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 E QC-time-services: Daemon:Update to modem bit set
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon:genoff_send_modem: Sending data to MODEM !
> clock_david_firstboot.log:04-17 16:27:08.098   265  1236 D QC-time-services: Daemon: Base = 2, Value being sent to MODEM = 1085618596622
> clock_david_firstboot.log:04-17 16:27:08.098   213   213 E QC-time-services: Receive Passed == base = 2, unit = 1, operation = 0, result = 0
> clock_david_firstboot.log:04-17 16:27:08.108   265   559 E QC-time-services: Daemon:tod_update_ind_cb: Got Update from modem msg_id 40
> clock_david_firstboot.log:04-17 16:27:08.108   265   562 E QC-time-services: Daemon: Time-services: Waiting to acceptconnection

Comment 75

[:gerard-majax]

Attachment: clock_david_secondboot.log

This is the log after rebooting and exposing the crash. We can see that the restored time do not matches the saved one:

> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Unable to open filefor read
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_post_init:Error in accessing storage
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_pre_init::Base = 13
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon: Storage Name: ats_13 
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Opening File: /data/time/ats_13
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:time_persistent_memory_opr:Genoff Read operation 
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Unable to open filefor read
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_post_init:Error in accessing storage
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_pre_init::Base = 14
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon: Storage Name: ats_14 
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Opening File: /data/time/ats_14
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:time_persistent_memory_opr:Genoff Read operation 
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Unable to open filefor read
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_post_init:Error in accessing storage
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_init_config: Other bases initilized, exiting genoff_init
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Try setting default time
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_opr: Base = 1, val = 0, operation = 1
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon: genoff get for 1
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:rtc_get: Time read from RTC -- MM/DD/YY HH:MM:SS0/1/70 23:4:57
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Value read from RTC seconds = 83097000
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Value read from RTC seconds = 83097000
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Value read from generif offset = 1401583396622
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:Final Time = 1401666493622
> clock_david_secondboot.log:01-02 00:04:58.350   315   315 D QC-time-services: Daemon:genoff_boot_tod_init: Setting system time to sec =1401666493, nsec =622000000
> clock_david_secondboot.log:06-02 01:48:13.622   315   315 E QC-time-services: Daemon:genoff_boot_tod_init: Unable to set TOD at boot up
> clock_david_secondboot.log:06-02 01:48:13.622   315   315 E QC-time-services: Daemon: Unable to set TOD at boot up
> clock_david_secondboot.log:06-02 01:48:13.622   315   315 D QC-time-services: Daemon:genoff_modem_qmi_init: Initiallizing QMI 
> clock_david_secondboot.log:06-02 01:48:14.762   315   315 E QC-time-services: Daemon:genoff_modem_qmi_init: qmi_client_get_service_list returned -2num_services 0
> clock_david_secondboot.log:06-02 01:48:15.132   202   202 I AudioFlinger: Using default 3000 mSec as standby time.
> clock_david_secondboot.log:06-02 01:48:15.172   486   486 D QSEECOMD: : Init dlopen(libdrmtime.so, RTLD_NOW) succeeds
> clock_david_secondboot.log:06-02 01:48:15.172   486   486 D QSEECOMD: : Init::Init dlsym(g_FSHandle atime_start) succeeds
> clock_david_secondboot.log:06-02 01:48:15.182   486   486 D QSEECOMD: : Init atime_start ret = 0
> clock_david_secondboot.log:06-02 01:48:15.182   486   486 D QSEECOMD: : time services: Started (Listener ID = 11)
> clock_david_secondboot.log:06-02 01:48:15.762   315   315 E QC-time-services: Daemon:genoff_modem_qmi_init: qmi_client_get_service_list returned 0num_services 1
> clock_david_secondboot.log:06-02 01:48:15.762   315   315 D QC-time-services: Daemon:rtc_get: Time read from RTC -- MM/DD/YY HH:MM:SS0/1/70 23:5:0
> clock_david_secondboot.log:06-02 01:48:15.762   315   315 D QC-time-services: Daemon:Value read from RTC seconds = 83100000
> clock_david_secondboot.log:06-02 01:48:15.762   315   315 D QC-time-services: Daemon:genoff_modem_qmi_init: Initial transaction successfull
> clock_david_secondboot.log:06-02 01:48:15.762   315   557 E QC-time-services: Daemon:tod_update_ind_cb: Got Update from modem msg_id 40
> clock_david_secondboot.log:06-02 01:48:15.762   315   559 D QC-time-services: Daemon: Time-services: All initializations done
> clock_david_secondboot.log:06-02 01:48:15.762   315   559 E QC-time-services: Daemon: Time-services: Waiting to acceptconnection
> clock_david_secondboot.log:06-02 01:48:15.832   219   219 I         : Starting bootanimation with (1) format framebuffer
> clock_david_secondboot.log:04-17 15:43:08.510   219   219 I Gecko   : *** UTM:SVC TimerManager:registerTimer - id: user-agent-updates-timer
> clock_david_secondboot.log:04-17 15:43:08.510   219   219 I GeckoConsole: UTM:SVC TimerManager:registerTimer - id: user-agent-updates-timer
> clock_david_secondboot.log:04-17 15:43:08.640   952   952 D wpa_supplicant: EAPOL: disable timer tick
> clock_david_secondboot.log:04-17 15:43:35.730   952   952 D wpa_supplicant: Scan requested (ret=0) - scan timeout 10 seconds
> clock_david_secondboot.log:04-17 15:43:52.860   219   891 F MOZ_Assert: Assertion failure: timestamp <= PR_Now(), at ../../../../moz-central/dom/quota/QuotaManager.cpp:2291

Comment 76

[:gerard-majax]

Bhavana, we would really need some help from partner to understand the behavior here. Please note it's on a Flame using b2g_time component.

Comment 78

[:gerard-majax]

Mike, can you have a look at comment 76 and comment 70 ? Thanks!

Comment 79

[Michael Wu [:mwu]]

Comment on attachment 8589677 [details] [review]
Device PR

Can't remove this without having the equivalent xpcom service installed here.

Comment 80

[Mike Lee [:mlee]]

(In reply to Alexandre LISSY :gerard-majax from comment #76)
> Bhavana, we would really need some help from partner to understand the
> behavior here. Please note it's on a Flame using b2g_time component.

Inder,

Please have someone from CAF respond here. Our engineering team needs additional information to move forward on this.

Thanks,
Mike

Comment 81

[Mike Lee [:mlee]]

Following up via email as this issue requires discussing proprietary code.

Comment 82

[Wesly Huang (EPM)]

Hi Youlong:

As mentioned in phone, please help follow this issue with QCT since this involves their proprietary. Once there is a fix:

1. For KK, we might consider a binary release from T2M (since no KK SW release plan at this moment) with the fix.
2. For L, we expect there is no such issue (or need a fix if exist in current delivery).

Thank you!

Comment 83

[youlong.jiang]

(In reply to Wesly Huang from comment #82)
> Hi Youlong:
> 
> As mentioned in phone, please help follow this issue with QCT since this
> involves their proprietary. Once there is a fix:
> 
> 1. For KK, we might consider a binary release from T2M (since no KK SW
> release plan at this moment) with the fix.
> 2. For L, we expect there is no such issue (or need a fix if exist in
> current delivery).
> 
> Thank you!

Dears -

we've apply for a new SR to follow this problem with Qcom, the number as follow '01993497'

tks.

Comment 84

[Wesly Huang (EPM)]

Thanks Youlong, please keeps us updated the result!

Comment 85

[youlong.jiang]

(In reply to Wesly Huang from comment #84)
> Thanks Youlong, please keeps us updated the result!

hi wesly -

about this problem, could you pls help push qcom RD to take over it. the current support team have no ability to handle it that need other team cooperate. so pls push qcom transfer this SR internally.

tks.

Comment 86

[Mike Lee [:mlee]]

Adding needinfo for comment 85.

Comment 87

[Wesly Huang (EPM)]

(In reply to youlong.jiang from comment #85)
> (In reply to Wesly Huang from comment #84)
> > Thanks Youlong, please keeps us updated the result!
> 
> hi wesly -
> 
> about this problem, could you pls help push qcom RD to take over it. the
> current support team have no ability to handle it that need other team
> cooperate. so pls push qcom transfer this SR internally.
> 
> tks.

Hi Ravi:

Would you talk to QCT for this (case#: SR 01993497)? Will mail to you for more detail. Thanks.

Comment 88

[Ravi Dandu]

Inder, SR 01993497 between T2M and QC has been filed to handle this bug. Please follow up there to give T2M the resolution.

Comment 89

[Wesly Huang (EPM)]

Note: Per QCT feedback they will look into this issue after CS, so should revisit this one after May/E.

Comment 90

[alex_mayorga]

Is this why the Flame clock is always out of wack upon restart or is that a different bug?

Comment 91

[Martijn Wargers (dead)]

(In reply to alex_mayorga from comment #90)
> Is this why the Flame clock is always out of wack upon restart or is that a
> different bug?

That's bug 1061797.

Comment 92

[Matěj Cepl]

(In reply to Martijn Wargers [:mwargers] (QA) from comment #91)
> (In reply to alex_mayorga from comment #90)
> > Is this why the Flame clock is always out of wack upon restart or is that a
> > different bug?
> 
> That's bug 1061797.

Except that bug was closed as a dupe of this one.

Comment 93

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

(In reply to alex_mayorga from comment #90)
> Is this why the Flame clock is always out of wack upon restart or is that a
> different bug?

seems so
I files bug 1088530 before but it's been duplicated with this bug.

Comment 96

[Gregor Wagner [:gwagner]]

Any updates here?

Comment 97

[Josh Cheng [:josh]]

Hi Gregor,
Per comment 89, this is POVB and QCT feedback they will look into this issue after CS, so should revisit this one after May/E.
remove 2.2+, please NI for any concern. Thanks.

Comment 99

[Seth Fowler [:seth] [:s2h]]

Please fix this *ASAP*. Debug Flame builds with a 319MB memory limit enter an infinite reboot loop because of this assertion, and this is a configuration that we care about and need to test against. This is wasting developer time and making it harder to meet deadlines.

If nobody is willing to take ownership for this very soon, we should just remove the assertion.

Comment 100

[Gregor Wagner [:gwagner]]

(In reply to Josh Cheng [:josh] from comment #97)
> Hi Gregor,
> Per comment 89, this is POVB and QCT feedback they will look into this issue
> after CS, so should revisit this one after May/E.
> remove 2.2+, please NI for any concern. Thanks.

Any updates? :)

Comment 101

[Josh Cheng [:josh]]

Hi Wesly,
Per comment 100, can you help to check with T2M about their progress?
Thanks.

Comment 102

[Wesly Huang (EPM)]

Hi Youlong:

As discussed in phone would you help update us the status/progress of SR 01993497 today? If no good news please help urge for it and let us know, so we can act from our side, too. Thanks.

Comment 103

[youlong.jiang]

(In reply to Wesly Huang from comment #102)
> Hi Youlong:
> 
> As discussed in phone would you help update us the status/progress of SR
> 01993497 today? If no good news please help urge for it and let us know, so
> we can act from our side, too. Thanks.

Dear Wesly -

I've confirm the SR status that no update from qcom, and was closed.

I Create a new SR for following this problem, number as below:

02071591

any problem, feel free to contact me.

tks.

Comment 104

[Wesly Huang (EPM)]

> (In reply to youlong.jiang from comment #103)
> Dear Wesly -
> I've confirm the SR status that no update from qcom, and was closed.
> I Create a new SR for following this problem, number as below:
> 02071591

(Thanks Youlong)

Hi Ravi:

Looks we still need QCT internally to put effort on it (updated SR# 02071591) , would you help talk to proper QCT contact? (Is it still Inder for it, like comment#88?) Thanks.

Comment 105

[Ravi Dandu]

Inder, Now that 2.2 CS is over, can QC investigate SR 01993497 from T2M.

Comment 106

[youlong.jiang]

Attachment: time_daemon

Comment 107

[youlong.jiang]

Attachment: libtime_genoff.so

Comment 108

[youlong.jiang]

Dear wesly -

we've got feedback from qcom that need to re-catch logcat when issue reproduce with new patched binary/lib. then pls help arrange to handle.

update binary as below:

adb push time_daemon /system/bin/
adb push libtime_genoff.so /system/vendor/lib/

if any problem feel free to contact me.

tks.

Comment 109

[Wesly Huang (EPM)]

(In reply to youlong.jiang from comment #108)
> Dear wesly -
> 
> we've got feedback from qcom that need to re-catch logcat when issue
> reproduce with new patched binary/lib. then pls help arrange to handle.
> 
> update binary as below:
> 
> adb push time_daemon /system/bin/
> adb push libtime_genoff.so /system/vendor/lib/
> 
> if any problem feel free to contact me.
> 
> tks.

Hi Yoshi:

Would you help generate needed log w/ the binary/lib QCT provided? Thanks!

Comment 110

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

Sorry I am busy with other stuff, and I am not working on this area.
There should be other better canidate to help analyse/reproduce this.

Comment 111

[Wesly Huang (EPM)]

(No problem Yoshi!)

Hi Alexandre:

I see you've put lots effort on this issue (~this April) right before QC's involvement, now QCT has people looking into it and need log per comment#108, do you think it's possible for you to help on this? 

Thanks in advance!

> we've got feedback from qcom that need to re-catch logcat when issue
> reproduce with new patched binary/lib. then pls help arrange to handle.
> 
> update binary as below:
> 
> adb push time_daemon /system/bin/
> adb push libtime_genoff.so /system/vendor/lib/

Comment 112

[:gerard-majax]

(In reply to Wesly Huang from comment #111)
> (No problem Yoshi!)
> 
> Hi Alexandre:
> 
> I see you've put lots effort on this issue (~this April) right before QC's
> involvement, now QCT has people looking into it and need log per
> comment#108, do you think it's possible for you to help on this? 
> 
> Thanks in advance!
> 
> > we've got feedback from qcom that need to re-catch logcat when issue
> > reproduce with new patched binary/lib. then pls help arrange to handle.
> > 
> > update binary as below:
> > 
> > adb push time_daemon /system/bin/
> > adb push libtime_genoff.so /system/vendor/lib/

Sorry, but this was a priority months ago. Now I need to focus on other more urgent stuff.
So no, I don't have time to help. If it's a problem, check with my manager.

Comment 113

[Gabriele Svelto [:gsvelto] (PTO)]

Wesly, I may have some spare cycles (and a spare Flame) for doing this. Just give me a full STR and I'll post a log as soon as possible.

Comment 114

[Wesly Huang (EPM)]

(In reply to Alexandre LISSY :gerard-majax from comment #112)
> Sorry, but this was a priority months ago. Now I need to focus on other more
> urgent stuff.
> So no, I don't have time to help. If it's a problem, check with my manager.

No problem, Alexandre, thanks for the prompt reply!

Comment 115

[Wesly Huang (EPM)]

(In reply to Gabriele Svelto [:gsvelto] from comment #113)
> Wesly, I may have some spare cycles (and a spare Flame) for doing this. Just
> give me a full STR and I'll post a log as soon as possible.

Thank you, Gabriele!

My understanding is to load debug build, reboot after initial boot will be enough to trigger this assert. Though in https://bugzilla.mozilla.org/show_bug.cgi?id=1164504#c1 it's said you need to use "adb reboot".

So what will be needed now is to follow QCT's feedback in comment#108 (paste below) to push those binary/lib then get desired log w/ the STR for QCT's further investigation.

Thanks in advance!

> we've got feedback from qcom that need to re-catch logcat when issue
> reproduce with new patched binary/lib. then pls help arrange to handle.
> 
> update binary as below:
> 
> adb push time_daemon /system/bin/
> adb push libtime_genoff.so /system/vendor/lib/

Comment 116

[Gabriele Svelto [:gsvelto] (PTO)]

OK, I'll give it a spin next week.

Comment 117

[Gabriele Svelto [:gsvelto] (PTO)]

I've tested the new binaries provided in attachment 8629789 [details] and attachment 8629790 [details] and the issue is still present. My STR is the following:

- Push the new binaries on the phone as per comment 108
- Flash a gecko/gaia debug build on my Flame
- Reboot the phone with 'adb reboot'

I'm using the v18D_v3 base build with today's mozilla-central checkout.

Comment 118

[Gabriele Svelto [:gsvelto] (PTO)]

Attachment: time_assertion.log

Here's the logcat of my run.

Comment 120

[Wesly Huang (EPM)]

(Much thanks to Gabriele's help!)

@Youlong:

Please help pass the log attached in comment#118 to QCT per their request, and keep us updated for their reply, thank you!

Comment 121

[youlong.jiang]

hi all -

qcom has closed issue related case again per long time without feedback, and i re-open a new one for tracking, case:02097737

tks.

Comment 122

[Josh Cheng [:josh]]

Wesly,
Do we still want to keep this open for 2.2?

Comment 123

[Wesly Huang (EPM)]

Hi Josh:

I may not be the best one to answer but my view is it's a long time pain-point of Flame as time reset after reboot, so if will be good if there is a fix for it, yet not necessarily for 2.2. (I remember we have time reset problem since 2.0 so this is not 2.2 regression) BTW from TAM team I don't see OEM partners report this issue as blocker of existing releases.


In the mean time 2 relevant things might be worth considering:

1. Since we are moving focus to Aries, does this issue still get same importance as before?

2. If in the end we do have a fix from QCT, do we really need a new Flame official release (eg v18E) for it? The support period w/ T2M is finished so it's unlikely T2M will help on a new release, my hope is we can have this fix in small binary format (still need T2M's support) so include it in our pvt or nightly build.

Comment 124

[Clément Lefèvre]

Wesly, most of the employees have now moved to Aries, yeah, but a lot of contributors are actively dogfooding with Flame, so I guess taking care of it would be nice too :)

Comment 125

[youlong.jiang]

hi, wesly -

about SR02097737, it's not related to time service problem from log they analysis, now issue is blocked and no move on. could you help push qcom interface to lead.

tks.

Comment 126

[Wesly Huang (EPM)]

(In reply to youlong.jiang from comment #125)
> hi, wesly -
> 
> about SR02097737, it's not related to time service problem from log they
> analysis, now issue is blocked and no move on. could you help push qcom
> interface to lead.
> 
> tks.

Hi Youlong, we have discussion w/ QCT ongoing for this, thank you for the update!

Comment 127

[Josh Cheng [:josh]]

Close for now per comment 125 and we now focus on Aries-L. 
Will open new one when we get Qualcomm response per comment 125.

Comment 128

[Peter Wu]

(not a Firefox OS user, the following is from an Android perspective intended to share knowledge.)

The libtime_genoff.so and time_daemon binaries only seem to read from the RTC and then write the offset to /data/system/time/ats_X (not to the RTC). Even after patching the kernel to enable the qcom,qpnp-rtc-write property, it still refused to apply the change.

Could it be that time modification is only possible through some other processor such as radio?

I have posted some more details and references at http://forum.xda-developers.com/showpost.php?p=62329019&postcount=3

Comment 129

[Dave Hylands [:dhylands]]

I'm still seeing this building for aries or flame (kitkat) on the latest master. If I reboot the phone then it goes into an infinite reboot loop with the ASSERT: Assertion failure: timestamp <= PR_Now(), at /home/work/B2G-aries/b2g-inbound/dom/quota/QuotaManager.cpp:3311 which essentially makes debugging anything in gecko on the phone extremely painful as I have to reflash in order to make it boot once.

Comment 130

[Dave Hylands [:dhylands]]

So if I'm reading things properly, if the user accidently set the time on their phone a month in the future and then corrects it back to the correct time, then our code will crash?

Comment 131

[James Cheng[:JamesCheng]]

As comment 129 mentioned, I also met this assertion on Nexus5 in latest master. I need to re-flash the image once I met this assertion...
Why this bug marked as WONTFIX?

Comment 132

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to James Cheng[:JamesCheng] from comment #131)
> As comment 129 mentioned, I also met this assertion on Nexus5 in latest
> master. I need to re-flash the image once I met this assertion...
> Why this bug marked as WONTFIX?

Because we needed vendor help for fixing this and we couldn't get it IIRC.

Comment 133

[Dave Hylands [:dhylands]]

I contest that the assertion is invalid. You can't use walltime to timestamp stuff and expect that it will never go backwards.

Comment 134

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Dave Hylands [:dhylands] from comment #133)
> I contest that the assertion is invalid. You can't use walltime to timestamp
> stuff and expect that it will never go backwards.

Isn't the problem related to the fact that the time stamp is being written to disk? I mean, no matter what timer you use - even a monotonic one - there's no guarantee that the timestamps you get will be coherent with those you had in a previous run (and that you wrote to disk).

Comment 135

[Fernando Jiménez Moreno [:ferjm]]

This bug makes debugging bugs like bug 1225121 impossible.

Comment 136

[Fernando Jiménez Moreno [:ferjm]]

s/impossible/terribly painful

(we can do adb shell stop|start b2g)

Comment 137

[Dave Hylands [:dhylands]]

(In reply to Gabriele Svelto [:gsvelto] from comment #134)
> (In reply to Dave Hylands [:dhylands] from comment #133)
> > I contest that the assertion is invalid. You can't use walltime to timestamp
> > stuff and expect that it will never go backwards.
> 
> Isn't the problem related to the fact that the time stamp is being written
> to disk? I mean, no matter what timer you use - even a monotonic one -
> there's no guarantee that the timestamps you get will be coherent with those
> you had in a previous run (and that you wrote to disk).

I think that the correct way to do this is that the timestamp has to be monotonic and not associated with time (wall-time or otherwise).

The timestamp could be some type of incrementing counter. The value of the counter should also be persisted on disk.

Ideally, if the timestamp is persisted in a database, then the 'timestamp' should be updated in the same transaction as the data.

Another approach, would be to create a "composite timestamp". Have a boot counter which increments each time the phone boots. Combine that with a monotonic timestamp from the OS. This has the advantage that the boot counter only needs to be incremented once per boot.