1107705 - Timestamp failure in QuotaManager

Status: RESOLVED DUPLICATE of bug 1110010

(Firefox OS Graveyard :: General, defect)

Description

[Thomas Zimmermann [:tzimmermann] [:tdz]]

I pushed some files to /storage/sdcard while b2g was still booting. I triggered the assertion shown below. Rev is 218287:a9fc46355661

F/MOZ_Assert( 1246): Assertion failure: timestamp <= PR_Now(), at ../../../../mozilla-central/dom/quota/QuotaManager.cpp:2515
F/libc    ( 1246): Fatal signal 11 (SIGSEGV) at 0x00000000 (code=1), thread 1299 (Storage I/O)

Comment 1

[Thomas Zimmermann [:tzimmermann] [:tdz]]

I've seen this again during startup on the Flame.

F/MOZ_Assert( 3347): Assertion failure: timestamp <= PR_Now(), at ../../../../mozilla-central/dom/quota/QuotaManager.cpp:2387
F/libc    ( 3347): Fatal signal 11 (SIGSEGV) at 0x00000000 (code=1), thread 3405 (Storage I/O)

Comment 2

[Thomas Zimmermann [:tzimmermann] [:tdz]]

The problem is certainly related to the missing RTC on the Flame. When the Flame boots up, the clock might be set to an incorrect time before the time of the last shutdown. And the assertion fails.

Dave, do you think there's a way to work around this problem in QuotaManager?

Comment 3

[Dave Hylands [:dhylands]]

Do you know whether /storage/sdcard was mounted or not?

During booting, it will be an empty directory in the initial ramdisk. During the booting process, vold will mount the sdcard onto that directory, and any files which may be present will effecitvely disappear until the volume is unmounted, at which point they'll magically appear again.

This is standard linux behaviour.

Is the QuotaManager trying to access/manipulate stuff on sdcard? If so, then it probably needs to listen to volume notifications to figure out if the volume is even accessible or not.

Comment 4

[Thomas Zimmermann [:tzimmermann] [:tdz]]

(In reply to Dave Hylands [:dhylands] from comment #3)
> Do you know whether /storage/sdcard was mounted or not?

I think so. Here's the output of 'mount'

root@flame:/ # mount                                                           
rootfs / rootfs ro,relatime 0 0
tmpfs /dev tmpfs rw,seclabel,nosuid,relatime,mode=755 0 0
devpts /dev/pts devpts rw,seclabel,relatime,mode=600 0 0
proc /proc proc rw,relatime 0 0
sysfs /sys sysfs rw,seclabel,relatime 0 0
selinuxfs /sys/fs/selinux selinuxfs rw,relatime 0 0
debugfs /sys/kernel/debug debugfs rw,relatime 0 0
none /acct cgroup rw,relatime,cpuacct 0 0
none /sys/fs/cgroup tmpfs rw,seclabel,relatime,mode=750,gid=1000 0 0
tmpfs /mnt/asec tmpfs rw,seclabel,relatime,mode=755,gid=1000 0 0
tmpfs /mnt/obb tmpfs rw,seclabel,relatime,mode=755,gid=1000 0 0
none /dev/cpuctl cgroup rw,relatime,cpu 0 0
/dev/block/platform/msm_sdcc.1/by-name/system /system ext4 ro,seclabel,relatime,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/userdata /data ext4 rw,seclabel,nosuid,nodev,relatime,noauto_da_alloc,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/cache /cache ext4 rw,seclabel,nosuid,nodev,relatime,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/persist /persist ext4 rw,seclabel,nosuid,nodev,relatime,data=ordered 0 0
/dev/block/platform/msm_sdcc.1/by-name/modem /firmware vfat ro,relatime,uid=1000,gid=1000,fmask=0337,dmask=0227,codepage=cp437,iocharset=iso8859-1,shortname=lower,errors=remount-ro 0 0
/dev/fuse /storage/usbotg fuse rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,allow_other 0 0
/dev/fuse /storage/sdcard1 fuse rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,allow_other 0 0
/dev/fuse /storage/uicc0 fuse rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,allow_other 0 0
/dev/fuse /storage/sdcard fuse rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,allow_other 0 0
/dev/block/vold/179:30 /mnt/media_rw/sdcard vfat rw,dirsync,nosuid,nodev,noexec,relatime,uid=1023,gid=1023,fmask=0007,dmask=0007,allow_utime=0020,codepage=cp437,iocharset=iso8859-1,shortname=mixed,utf8,errors=remount-ro 0 0


> During booting, it will be an empty directory in the initial ramdisk. During
> the booting process, vold will mount the sdcard onto that directory, and any
> files which may be present will effecitvely disappear until the volume is
> unmounted, at which point they'll magically appear again.

The content of the sdcard is

root@flame:/ # ls /storage/sdcard                                              
LOST.DIR
root@flame:/ # ls /storage/sdcard/LOST.DIR/                                    
root@flame:/ # 

> 
> This is standard linux behaviour.
> 
> Is the QuotaManager trying to access/manipulate stuff on sdcard? If so, then
> it probably needs to listen to volume notifications to figure out if the
> volume is even accessible or not.

Does 'sdcard' in this context mean 'physical SD Card'? Because I don't actually have one inserted in the device's slot.

Comment 5

[Thomas Zimmermann [:tzimmermann] [:tdz]]

Here is the stack trace for the assertion.

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 2453.2533]
0xb4f8ee5a in mozilla::dom::quota::QuotaManager::EnsureOriginIsInitialized (this=this@entry=0xafce7b80, 
    aPersistenceType=aPersistenceType@entry=mozilla::dom::quota::PERSISTENCE_TYPE_PERSISTENT, aGroup=..., aOrigin=..., aIsApp=aIsApp@entry=false, 
    aHasUnlimStoragePerm=aHasUnlimStoragePerm@entry=false, aDirectory=0xaf8c1988) at ../../../../mozilla-central/dom/quota/QuotaManager.cpp:2377
2377          MOZ_ASSERT(timestamp <= PR_Now());
(gdb) bt
#0  0xb4f8ee5a in mozilla::dom::quota::QuotaManager::EnsureOriginIsInitialized (this=this@entry=0xafce7b80, 
    aPersistenceType=aPersistenceType@entry=mozilla::dom::quota::PERSISTENCE_TYPE_PERSISTENT, aGroup=..., aOrigin=..., aIsApp=aIsApp@entry=false, 
    aHasUnlimStoragePerm=aHasUnlimStoragePerm@entry=false, aDirectory=0xaf8c1988) at ../../../../mozilla-central/dom/quota/QuotaManager.cpp:2377
#1  0xb502bec0 in mozilla::dom::indexedDB::(anonymous namespace)::OpenDatabaseOp::DoDatabaseWork (this=0xb19747a0)
    at ../../../../mozilla-central/dom/indexedDB/ActorsParent.cpp:11292
#2  0xb50205c2 in mozilla::dom::indexedDB::(anonymous namespace)::FactoryOp::Run (this=0xb19747a0)
    at ../../../../mozilla-central/dom/indexedDB/ActorsParent.cpp:11136
#3  0xb43d3430 in nsThread::ProcessNextEvent (this=0xafec5a80, aMayWait=<optimized out>, aResult=0xaf8c1cf7)
    at ../../../../mozilla-central/xpcom/threads/nsThread.cpp:855
#4  0xb43e7be0 in NS_ProcessNextEvent (aThread=0xafec5a80, aMayWait=aMayWait@entry=false)
    at /home/mozilla/Projects/mozilla/src/mozilla-central/xpcom/glue/nsThreadUtils.cpp:265
#5  0xb459c6fc in mozilla::ipc::MessagePumpForNonMainThreads::Run (this=0xafcd1cd0, aDelegate=0xafc6eda0)
    at ../../../../mozilla-central/ipc/glue/MessagePump.cpp:339
#6  0xb4589190 in MessageLoop::RunInternal (this=this@entry=0xafc6eda0) at ../../../../mozilla-central/ipc/chromium/src/base/message_loop.cc:233
#7  0xb45891aa in RunHandler (this=0xafc6eda0) at ../../../../mozilla-central/ipc/chromium/src/base/message_loop.cc:226
#8  MessageLoop::Run (this=this@entry=0xafc6eda0) at ../../../../mozilla-central/ipc/chromium/src/base/message_loop.cc:200
#9  0xb43d409c in nsThread::ThreadFunc (aArg=0xafec5a80) at ../../../../mozilla-central/xpcom/threads/nsThread.cpp:356
#10 0xb6a4c8e8 in _pt_root (arg=0xafa01f00) at ../../../../../../mozilla-central/nsprpub/pr/src/pthreads/ptthread.c:212
#11 0xb6f0c22c in __thread_entry (func=0xb6a4c841 <_pt_root>, arg=0xafa01f00, tls=0xaf8c1dd0) at bionic/libc/bionic/pthread_create.cpp:105
#12 0xb6f0c3c4 in pthread_create (thread_out=0xbef28604, attr=<optimized out>, start_routine=0xb6a4c841 <_pt_root>, arg=0x78)
    at bionic/libc/bionic/pthread_create.cpp:224
#13 0x00000000 in ?? ()
(gdb)

Comment 6

[Thomas Zimmermann [:tzimmermann] [:tdz]]

FYI, I can boot after flashing the phone, but restarting the phone always fails.

Comment 7

[Dave Hylands [:dhylands]]

(In reply to Thomas Zimmermann [:tzimmermann] [:tdz] from comment #4)
> (In reply to Dave Hylands [:dhylands] from comment #3)
> > Do you know whether /storage/sdcard was mounted or not?
> 
> I think so. Here's the output of 'mount'
> 
> root@flame:/ # mount                                                        
> 
> rootfs / rootfs ro,relatime 0 0
> tmpfs /dev tmpfs rw,seclabel,nosuid,relatime,mode=755 0 0
> devpts /dev/pts devpts rw,seclabel,relatime,mode=600 0 0
> proc /proc proc rw,relatime 0 0
> sysfs /sys sysfs rw,seclabel,relatime 0 0
> selinuxfs /sys/fs/selinux selinuxfs rw,relatime 0 0
> debugfs /sys/kernel/debug debugfs rw,relatime 0 0
> none /acct cgroup rw,relatime,cpuacct 0 0
> none /sys/fs/cgroup tmpfs rw,seclabel,relatime,mode=750,gid=1000 0 0
> tmpfs /mnt/asec tmpfs rw,seclabel,relatime,mode=755,gid=1000 0 0
> tmpfs /mnt/obb tmpfs rw,seclabel,relatime,mode=755,gid=1000 0 0
> none /dev/cpuctl cgroup rw,relatime,cpu 0 0
> /dev/block/platform/msm_sdcc.1/by-name/system /system ext4
> ro,seclabel,relatime,data=ordered 0 0
> /dev/block/platform/msm_sdcc.1/by-name/userdata /data ext4
> rw,seclabel,nosuid,nodev,relatime,noauto_da_alloc,data=ordered 0 0
> /dev/block/platform/msm_sdcc.1/by-name/cache /cache ext4
> rw,seclabel,nosuid,nodev,relatime,data=ordered 0 0
> /dev/block/platform/msm_sdcc.1/by-name/persist /persist ext4
> rw,seclabel,nosuid,nodev,relatime,data=ordered 0 0
> /dev/block/platform/msm_sdcc.1/by-name/modem /firmware vfat
> ro,relatime,uid=1000,gid=1000,fmask=0337,dmask=0227,codepage=cp437,
> iocharset=iso8859-1,shortname=lower,errors=remount-ro 0 0
> /dev/fuse /storage/usbotg fuse
> rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,
> allow_other 0 0
> /dev/fuse /storage/sdcard1 fuse
> rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,
> allow_other 0 0
> /dev/fuse /storage/uicc0 fuse
> rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,
> allow_other 0 0
> /dev/fuse /storage/sdcard fuse
> rw,nosuid,nodev,relatime,user_id=1023,group_id=1023,default_permissions,
> allow_other 0 0
> /dev/block/vold/179:30 /mnt/media_rw/sdcard vfat
> rw,dirsync,nosuid,nodev,noexec,relatime,uid=1023,gid=1023,fmask=0007,
> dmask=0007,allow_utime=0020,codepage=cp437,iocharset=iso8859-1,
> shortname=mixed,utf8,errors=remount-ro 0 0

That means that it was mounted at the time the mount command ran.

Mouting the sdcard volume is an async process during boot.

But if you were adding files during bootup, it may or may not have been mounted at the time.

> > During booting, it will be an empty directory in the initial ramdisk. During
> > the booting process, vold will mount the sdcard onto that directory, and any
> > files which may be present will effecitvely disappear until the volume is
> > unmounted, at which point they'll magically appear again.
> 
> The content of the sdcard is
> 
> root@flame:/ # ls /storage/sdcard                                           
> 
> LOST.DIR
> root@flame:/ # ls /storage/sdcard/LOST.DIR/                                 

That's expected in an empty mounted filesystem.

> > 
> > This is standard linux behaviour.
> > 
> > Is the QuotaManager trying to access/manipulate stuff on sdcard? If so, then
> > it probably needs to listen to volume notifications to figure out if the
> > volume is even accessible or not.
> 
> Does 'sdcard' in this context mean 'physical SD Card'? Because I don't
> actually have one inserted in the device's slot.

Some of our older phones only had an exteral sdcard and no internal sdcard, so in that case the physical sdcard was called sdcard. On phones like the flame, then internal sdcard is called sdcard and the physical card sdcard is called extsdcard.

If there is an internal storage area, it's called sdcard. If there is a separate partition for it and its formatted as vfat, then typically the mounting of it is managed by vold and thus async.

On phones like the nexus 4/5 sdcard and /data share the same partition, and sdcard isn't managed by vold, so it's "mounted" as part of running the init.rc scripts.