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

RESOLVED WONTFIX

Status

()

defect
RESOLVED WONTFIX
4 years ago
2 years ago

People

(Reporter: allstars.chh, Assigned: gerard-majax)

Tracking

({dogfood})

Trunk
ARM
Gonk (Firefox OS)
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(b2g-v2.2 affected, b2g-master affected)

Details

(Whiteboard: [POVB])

Attachments

(8 attachments, 7 obsolete attachments)

51 bytes, text/x-github-pull-request
Details | Review
7.37 KB, patch
gwagner
: review+
Details | Diff | Splinter Review
1.45 KB, text/plain
Details
500.22 KB, text/x-log
Details
251.19 KB, text/x-log
Details
17.39 KB, application/x-sharedlib
Details
9.09 KB, application/x-sharedlib
Details
84.86 KB, text/x-log
Details
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 <ryanvm@gmail.com>
Date:   Wed Dec 10 16:01:20 2014 -0500

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

Comment 1

4 years ago
Hm, there's must be a problem with system clock or something.
Ben, can we just remove this assertion ?
Flags: needinfo?(bent.mozilla)
Well, are you sure that nothing else breaks in the quota manager if the system time is artificially set back?
Flags: needinfo?(bent.mozilla)

Comment 3

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

Updated

4 years ago
Blocks: 1083927

Comment 4

4 years ago
This should be now fixed.
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
I am still seeing this issue with current trunk.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
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 ?? ()
I ran into this too, but at QuotaManager.cpp:2326
I see the assertion at line 2379. I worked around it in my local build by commenting it out.
Jan, can you take a look again?
Flags: needinfo?(Jan.Varga)
Gregor, do you think it's possible that the system clock on the device is sometimes set back ?
Flags: needinfo?(Jan.Varga)
(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.
ISTR the Tarako having issues being reset to the epoch if the battery runs out.  Is this still an issue?
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?
Flags: needinfo?(dhylands)
Flags: needinfo?(anygregor)
(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.
Flags: needinfo?(anygregor) → needinfo?(hkoka)
(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.
Flags: needinfo?(dhylands)
(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 :(
(In reply to Dave Hylands [:dhylands] from comment #15)
> We should be using sometime of monotonic incrementing number.

Do we have such a thing?
(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.
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.
Depends on: 1032101, 1000352
Flags: needinfo?(aosmond)
Andrew will help investigate this issue. Dave and Mike are pulled into something else.  

Thanks
Hema
Flags: needinfo?(hkoka)
(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
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.
(Assignee)

Comment 23

4 years ago
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.
(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.
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.)
Flags: needinfo?(aosmond) → needinfo?(mvines)
(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.
Flags: needinfo?(mvines)
(Assignee)

Comment 30

4 years ago
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
Flags: needinfo?(mvines)
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
Attachment #8566835 - Attachment is obsolete: true
Attachment #8566836 - Attachment is obsolete: true
Attachment #8566837 - Attachment is obsolete: true
Attachment #8568552 - Flags: feedback?(mwu)
Not sure I know what's going on well enough to answer your questions here..
See Also: → 1061797

Comment 33

4 years ago
time_daemon blob can be replaced with an open source implementation

https://github.com/sonyxperiadev/timekeep
(Assignee)

Updated

4 years ago
Blocks: 1143472
+'ed because of bug 1061797.
blocking-b2g: --- → 2.2+

Updated

4 years ago
Duplicate of this bug: 1061797
(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?
Flags: needinfo?(mwu)
Keywords: dogfood

Updated

4 years ago
Flags: needinfo?(mwu)

Comment 37

4 years ago
Hi Ben, do you have any feedback for the patch?
Flags: needinfo?(bent.mozilla)
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!
Flags: needinfo?(bent.mozilla)
Attachment #8568552 - Flags: review?(fabrice)
Attachment #8568552 - Flags: review?(bent.mozilla)
Attachment #8568552 - Flags: feedback?(mwu)
Assignee: nobody → aosmond
I applied the patch and still see F/MOZ_Assert( 1504): Assertion failure: timestamp <= PR_Now(), at ../../../dom/quota/QuotaManager.cpp:2331
(Assignee)

Comment 40

4 years ago
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.
(Assignee)

Comment 41

4 years ago
And timekeep does work quite well on my Flame also.
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
(Assignee)

Comment 43

4 years ago
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.
Flags: needinfo?(aosmond)
(Assignee)

Comment 44

4 years ago
Stealing to update
Assignee: aosmond → lissyx+mozillians
Flags: needinfo?(mvines)
Flags: needinfo?(aosmond)
(Assignee)

Updated

4 years ago
No longer blocks: 1143472
(Assignee)

Comment 45

4 years ago
We will need attachment 8582996 [details] [diff] [review] from 1146900
Depends on: 1146900
(Assignee)

Comment 46

4 years ago
Attachment #8568552 - Attachment is obsolete: true
Attachment #8568552 - Flags: review?(fabrice)
Attachment #8568552 - Flags: review?(bent.mozilla)
(Assignee)

Comment 47

4 years ago
(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.
(Assignee)

Comment 48

4 years ago
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.
Attachment #8589640 - Flags: review?(fabrice)
(Assignee)

Comment 49

4 years ago
Posted file Device PR
This blob become useless once we have QTimeService.
Attachment #8589677 - Flags: review?(mwu)
(Assignee)

Comment 50

4 years ago
I'm checking whether we may also need the same timeservice detection for timekeep users.
(Assignee)

Comment 51

4 years ago
Attachment #8589640 - Attachment is obsolete: true
Attachment #8589640 - Flags: review?(fabrice)
(Assignee)

Updated

4 years ago
Attachment #8589682 - Flags: review?(fabrice)
(Assignee)

Comment 52

4 years ago
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 ...
(Assignee)

Comment 53

4 years ago
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
Flags: needinfo?(Jan.Varga)
(Assignee)

Comment 54

4 years ago
Posted file Patch used to reproduce MOZ_ASSERT (obsolete) —
(Assignee)

Comment 55

4 years ago
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
Jan, isn't this the milliseconds vs. microseconds problem?
(Assignee)

Updated

4 years ago
Attachment #8590272 - Attachment is obsolete: true
(Assignee)

Comment 57

4 years ago
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().
Flags: needinfo?(Jan.Varga)
Yeah, those steps are guaranteed to trip this assertion. Jan, we should figure out how to handle this case.
(Assignee)

Comment 59

4 years ago
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.
(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.
Change component to register with the native time service to ensure observers get the desired notifications.
Attachment #8589682 - Attachment is obsolete: true
Attachment #8589682 - Flags: review?(fabrice)
Attachment #8590343 - Flags: review?(fabrice)
(Assignee)

Comment 62

4 years ago
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.
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)
Ah, bug 1110585 fixed the scale conversions...
(Assignee)

Comment 65

4 years ago
(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.
Flags: needinfo?(anygregor)
(Assignee)

Comment 66

4 years ago
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
Flags: needinfo?(aosmond)
(Assignee)

Comment 67

4 years ago
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."
(Assignee)

Comment 68

4 years ago
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 ?
Flags: needinfo?(anygregor)
(Assignee)

Updated

4 years ago
Flags: needinfo?(anygregor)
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.
Attachment #8590343 - Flags: review?(fabrice) → review?(anygregor)
(Assignee)

Comment 70

4 years ago
Michael, is it expected that we have the device restoring the very same clock between two reboots ?
Flags: needinfo?(mvines)

Updated

4 years ago
Summary: Assertion failure: timestamp <= PR_Now(), at ../../../gecko/dom/quota/QuotaManager.cpp:2379 → [Flame][Clock Time] After restarting the phone, the time and date displayed are wrong until there is a connection to the Internet
(Assignee)

Updated

4 years ago
Summary: [Flame][Clock Time] After restarting the phone, the time and date displayed are wrong until there is a connection to the Internet → Assertion failure: timestamp <= PR_Now(), at ../../../gecko/dom/quota/QuotaManager.cpp:2379
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
Attachment #8590343 - Flags: review?(anygregor) → review+
This component needs to land in a device repo since it is specific to CAF based devices. PRODUCT_COPY_FILES will do the trick.
(Assignee)

Comment 73

4 years ago
Reproduced on David's device, looks like reset-gaia on a debug build helps :)
(Assignee)

Comment 74

4 years ago
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
(Assignee)

Comment 75

4 years ago
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
(Assignee)

Comment 76

4 years ago
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.
Flags: needinfo?(bbajaj)
See Also: → 1155795
Duplicate of this bug: 1155795
(Assignee)

Comment 78

4 years ago
Mike, can you have a look at comment 76 and comment 70 ? Thanks!
Flags: needinfo?(mlee)
Comment on attachment 8589677 [details] [review]
Device PR

Can't remove this without having the equivalent xpcom service installed here.
Attachment #8589677 - Flags: review?(mwu)

Comment 80

4 years ago
(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
Flags: needinfo?(mlee) → needinfo?(ikumar)

Comment 81

4 years ago
Following up via email as this issue requires discussing proprietary code.
Flags: needinfo?(ikumar)
Flags: needinfo?(bbajaj)
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!
Flags: needinfo?(youlong.jiang)

Comment 83

4 years ago
(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.
Flags: needinfo?(youlong.jiang)
Thanks Youlong, please keeps us updated the result!
Flags: needinfo?(youlong.jiang)

Comment 85

4 years ago
(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.
Flags: needinfo?(youlong.jiang)

Comment 86

4 years ago
Adding needinfo for comment 85.
Flags: needinfo?(wehuang)
(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.
Flags: needinfo?(wehuang) → needinfo?(rdandu)

Comment 88

4 years ago
Inder, SR 01993497 between T2M and QC has been filed to handle this bug. Please follow up there to give T2M the resolution.
Flags: needinfo?(rdandu) → needinfo?(ikumar)
Note: Per QCT feedback they will look into this issue after CS, so should revisit this one after May/E.

Comment 90

4 years ago
Is this why the Flame clock is always out of wack upon restart or is that a different bug?
Flags: needinfo?(allstars.chh)
(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

4 years ago
(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.
(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.
Flags: needinfo?(allstars.chh)
Duplicate of this bug: 1164504
Duplicate of this bug: 1107705

Updated

4 years ago
Whiteboard: [POVB]
Flags: needinfo?(mvines)
Flags: needinfo?(ikumar)
Any updates here?
Flags: needinfo?(anygregor) → needinfo?(jocheng)
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.
blocking-b2g: 2.2+ → 2.2?

Updated

4 years ago
Flags: needinfo?(jocheng)
See Also: → 1168588
Duplicate of this bug: 1168588
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.
(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? :)
Flags: needinfo?(jocheng)

Updated

4 years ago
Blocks: 1174864
Hi Wesly,
Per comment 100, can you help to check with T2M about their progress?
Thanks.
Flags: needinfo?(jocheng) → needinfo?(wehuang)
See Also: → 1031573
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.
Flags: needinfo?(wehuang) → needinfo?(youlong.jiang)

Comment 103

4 years ago
(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.
Flags: needinfo?(youlong.jiang)
> (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.
Flags: needinfo?(rdandu)
Flags: needinfo?(ikumar)

Comment 105

4 years ago
Inder, Now that 2.2 CS is over, can QC investigate SR 01993497 from T2M.
Flags: needinfo?(rdandu)

Comment 106

4 years ago
Posted file time_daemon

Comment 107

4 years ago
Posted file libtime_genoff.so

Comment 108

4 years ago
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.

Updated

4 years ago
Flags: needinfo?(wehuang)
(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!
Flags: needinfo?(wehuang) → needinfo?(allstars.chh)
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.
Flags: needinfo?(allstars.chh)
(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/
Flags: needinfo?(lissyx+mozillians)
(Assignee)

Comment 112

4 years ago
(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.
Flags: needinfo?(lissyx+mozillians)
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.
(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!
(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/
Flags: needinfo?(gsvelto)
OK, I'll give it a spin next week.
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.
Flags: needinfo?(gsvelto)
Posted file time_assertion.log
Here's the logcat of my run.
Duplicate of this bug: 1179477
(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!
Flags: needinfo?(youlong.jiang)

Comment 121

4 years ago
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.
Flags: needinfo?(youlong.jiang)
Wesly,
Do we still want to keep this open for 2.2?
Flags: needinfo?(wehuang)
Flags: needinfo?(ikumar)
Flags: needinfo?(aosmond)
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.
Flags: needinfo?(wehuang)
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 :)

Updated

4 years ago
blocking-b2g: 2.2? → 2.5?

Comment 125

4 years ago
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.
Flags: needinfo?(wehuang)
(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!
Flags: needinfo?(wehuang)
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.
Status: REOPENED → RESOLVED
blocking-b2g: 2.5? → ---
Last Resolved: 4 years ago4 years ago
Resolution: --- → WONTFIX

Comment 128

4 years ago
(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
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.
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?
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?
(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.
I contest that the assertion is invalid. You can't use walltime to timestamp stuff and expect that it will never go backwards.
(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).
This bug makes debugging bugs like bug 1225121 impossible.
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---
s/impossible/terribly painful

(we can do adb shell stop|start b2g)
(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.
(Assignee)

Updated

2 years ago
Status: REOPENED → RESOLVED
Last Resolved: 4 years ago2 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.