log3.txt

2016-09-26 16:14:21.194910 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Init()
2016-09-26 16:14:21.194956 UTC - [Main Thread]: D/cache2 CacheFileHandles::CacheFileHandles() [this=7f00adf91600]
2016-09-26 16:14:21.194963 UTC - [Main Thread]: D/cache2 CacheFileIOManager::CacheFileIOManager [this=7f00adf915c0]
2016-09-26 16:14:21.195007 UTC - [Main Thread]: D/cache2 CacheFileIOManager::OnProfile() [gInstance=7f00adf915c0]
2016-09-26 16:14:21.195263 UTC - [Main Thread]: D/cache2 CacheIndex::Init()
2016-09-26 16:14:21.195274 UTC - [Main Thread]: D/cache2 CacheIndex::CacheIndex [this=7f00aecd1240]
2016-09-26 16:14:21.195279 UTC - [Main Thread]: D/cache2 CacheIndex::ReadIndexFromDisk()
2016-09-26 16:14:21.195283 UTC - [Main Thread]: D/cache2 CacheIndex::ChangeState() changing state INITIAL -> READING
2016-09-26 16:14:21.195290 UTC - [Main Thread]: D/cache2 CacheFileIOManager::CacheIndexStateChanged()
2016-09-26 16:14:21.195316 UTC - [Main Thread]: D/cache2 CacheFileIOManager::OpenFile() [key=index, flags=8, listener=7f00ae179910]
2016-09-26 16:14:21.195327 UTC - [Main Thread]: D/cache2 CacheFileIOManager::OpenFile() [key=index.log, flags=8, listener=7f00ae179940]
2016-09-26 16:14:21.195335 UTC - [Main Thread]: D/cache2 CacheFileIOManager::OpenFile() [key=index.tmp, flags=8, listener=7f00ae179970]
2016-09-26 16:14:21.195365 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenSpecialFileInternal() [key=index, flags=8]
2016-09-26 16:14:21.195479 UTC - [Cache2 I/O]: D/cache2 CacheFileContextEvictor::CacheFileContextEvictor() [this=7f00ae1799a0]
2016-09-26 16:14:21.195487 UTC - [Cache2 I/O]: D/cache2 CacheFileContextEvictor::Init()
2016-09-26 16:14:21.195492 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.195498 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.195508 UTC - [Cache2 I/O]: D/cache2 CacheFileContextEvictor::LoadEvictInfoFromDisk() [this=7f00ae1799a0]
2016-09-26 16:14:21.195550 UTC - [Cache2 I/O]: D/cache2 CacheFileContextEvictor::~CacheFileContextEvictor() [this=7f00ae1799a0]
2016-09-26 16:14:21.195557 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::StartRemovingTrash()
2016-09-26 16:14:21.195746 UTC - [Cache2 I/O]: D/cache2 CacheIndex::OnFileOpenedInternal() [opener=7f00ae179910, handle=0, result=0x80040111]
2016-09-26 16:14:21.195757 UTC - [Cache2 I/O]: D/cache2 CacheIndex::FinishRead() [succeeded=0]
2016-09-26 16:14:21.195764 UTC - [Cache2 I/O]: D/cache2 CacheIndex::ProcessPendingOperations()
2016-09-26 16:14:21.195770 UTC - [Cache2 I/O]: D/cache2 CacheIndex::StartUpdatingIndex() [rebuild=1]
2016-09-26 16:14:21.195775 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=0, notInitialized=0, removed=0, dirty=0, fresh=0, empty=0, size=0]
2016-09-26 16:14:21.195780 UTC - [Cache2 I/O]: D/cache2 CacheIndex::ChangeState() changing state READING -> BUILDING
2016-09-26 16:14:21.195784 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimit()
2016-09-26 16:14:21.195796 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::CacheIndexStateChanged()
2016-09-26 16:14:21.195811 UTC - [Cache2 I/O]: D/cache2 CacheIndex::StartUpdatingIndex() - 0 ms elapsed since startup, scheduling timer to fire in 50000 ms.
2016-09-26 16:14:21.195817 UTC - [Cache2 I/O]: D/cache2 CacheIndex::ScheduleUpdateTimer() [delay=50000]
2016-09-26 16:14:21.195852 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenSpecialFileInternal() [key=index.log, flags=8]
2016-09-26 16:14:21.195874 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenSpecialFileInternal() [key=index.tmp, flags=8]
2016-09-26 16:14:21.195891 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.196051 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.196059 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.196064 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.196070 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 0
2016-09-26 16:14:21.196077 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=0kB, cacheSizeLimit=256000kB, freeSpace=106634002432, freeSpaceLimit=5242880]
2016-09-26 16:14:21.219958 UTC - [Main Thread]: D/nsHttp Creating nsHttpHandler [this=7f00adf84000].
2016-09-26 16:14:21.220001 UTC - [Main Thread]: D/nsHttp nsHttpHandler::Init
2016-09-26 16:14:21.220206 UTC - [Main Thread]: D/nsHttp nsHttpHandler::PrefsChanged [pref=(null)]
2016-09-26 16:14:21.220219 UTC - [Main Thread]: D/nsHttp nsHttpHandler::PrefsChanged Security Pref Changed (null)
2016-09-26 16:14:21.221192 UTC - [Main Thread]: D/nsHttp nsHttpHandler::MakeNewRequestTokenBucket this=7f00adf84000 child=0
2016-09-26 16:14:21.221310 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::Init
2016-09-26 16:14:21.221322 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::Init
2016-09-26 16:14:21.221353 UTC - [Main Thread]: V/nsHttp Creating nsHttpConnectionMgr @7f00b887e1e0
2016-09-26 16:14:21.221376 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::Init
2016-09-26 16:14:21.221401 UTC - [Main Thread]: D/nsHttp > legacy-app-name = Mozilla
2016-09-26 16:14:21.221409 UTC - [Main Thread]: D/nsHttp > legacy-app-version = 5.0
2016-09-26 16:14:21.221415 UTC - [Main Thread]: D/nsHttp > platform = X11
2016-09-26 16:14:21.221422 UTC - [Main Thread]: D/nsHttp > oscpu = Linux x86_64
2016-09-26 16:14:21.221428 UTC - [Main Thread]: D/nsHttp > misc = rv:52.0
2016-09-26 16:14:21.221435 UTC - [Main Thread]: D/nsHttp > product = Gecko
2016-09-26 16:14:21.221441 UTC - [Main Thread]: D/nsHttp > product-sub = 20100101
2016-09-26 16:14:21.221448 UTC - [Main Thread]: D/nsHttp > app-name = 
2016-09-26 16:14:21.221454 UTC - [Main Thread]: D/nsHttp > app-version = 52.0a1
2016-09-26 16:14:21.221461 UTC - [Main Thread]: D/nsHttp > compat-firefox = Firefox/52.0
2016-09-26 16:14:21.221468 UTC - [Main Thread]: D/nsHttp nsHttpHandler::BuildUserAgent
2016-09-26 16:14:21.221502 UTC - [Main Thread]: D/nsHttp > user-agent = Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 /52.0a1
2016-09-26 16:14:21.221561 UTC - [Main Thread]: D/nsHttp nsHttpHandler::MakeNewRequestTokenBucket this=7f00adf84000 child=0
2016-09-26 16:14:21.225268 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NewProxiedChannel [proxyInfo=0]
2016-09-26 16:14:21.225331 UTC - [Main Thread]: V/nsHttp Creating HttpBaseChannel @adf56000
2016-09-26 16:14:21.225350 UTC - [Main Thread]: D/nsHttp Creating nsHttpChannel [this=7f00adf56000]
2016-09-26 16:14:21.233655 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::Init [this=7f00adf56000]
2016-09-26 16:14:21.233686 UTC - [Main Thread]: V/nsHttp host=localhost port=34047
2016-09-26 16:14:21.233692 UTC - [Main Thread]: V/nsHttp uri=http://localhost:34047/content
2016-09-26 16:14:21.233708 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Init [this=7f00adf56000]
2016-09-26 16:14:21.235459 UTC - [Main Thread]: D/nsHttp nsHttpChannel::AsyncOpen [this=7f00adf56000]
2016-09-26 16:14:21.348375 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=7f00adf56000 header="Cookie" value="" merge=0]
2016-09-26 16:14:21.348442 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adf56058 event="http-on-opening-request"]
2016-09-26 16:14:21.348501 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ResolveProxy [this=7f00adf56000]
2016-09-26 16:14:21.352392 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnProxyAvailable [this=7f00adf56000 pi=0 status=0 mStatus=0]
2016-09-26 16:14:21.352439 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=7f00adf56000]
2016-09-26 16:14:21.352461 UTC - [Main Thread]: D/nsHttp host=localhost port=34047
2016-09-26 16:14:21.352473 UTC - [Main Thread]: D/nsHttp uri=http://localhost:34047/content
2016-09-26 16:14:21.352953 UTC - [Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7f00b887e1e8 http:localhost:34047:.
2016-09-26 16:14:21.353077 UTC - [Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7f00b887e1e8 MISS
2016-09-26 16:14:21.353114 UTC - [Main Thread]: D/nsHttp AltSvcCache::GetAltServiceMapping 7f00b887e1e8 key=http:localhost:34047:. existing=0 validated=0 ttl=0
2016-09-26 16:14:21.353154 UTC - [Main Thread]: D/nsHttp nsHttpChannel 7f00adf56000 Using default connection info
2016-09-26 16:14:21.353183 UTC - [Main Thread]: V/nsHttp Init nsHttpConnectionInfo @7f00b8878da0
2016-09-26 16:14:21.353415 UTC - [Main Thread]: D/nsHttp nsHttpChannelAuthProvider::AddAuthorizationHeaders? [this=7f00ac093200 channel=7f00adf56538]
2016-09-26 16:14:21.353488 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::GetAuthEntryForPath [key=http://localhost:34047 path=/]
2016-09-26 16:14:21.353531 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adf56058 event="http-on-modify-request"]
2016-09-26 16:14:21.353632 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=7f00adf56000] prefetching
2016-09-26 16:14:21.353946 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult [this=7f00adf56000]
2016-09-26 16:14:21.353978 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Connect [this=7f00adf56000]
2016-09-26 16:14:21.354283 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::SpeculativeConnect [ci=......localhost:34047]
2016-09-26 16:14:21.354467 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OpenCacheEntry [this=7f00adf56000]
2016-09-26 16:14:21.354550 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Init()
2016-09-26 16:14:21.354558 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgSpeculativeConnect [ci=......localhost:34047]
2016-09-26 16:14:21.354637 UTC - [Socket Thread]: V/nsHttp Init nsHttpConnectionInfo @7f00b8878cc0
2016-09-26 16:14:21.354737 UTC - [Main Thread]: D/cache2 CacheStorageService::AddStorageEntry [entryKey=:http://localhost:34047/content, contextKey=]
2016-09-26 16:14:21.354777 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::AtActiveConnectionLimit [ci=......localhost:34047 caps=401]
2016-09-26 16:14:21.354779 UTC - [Main Thread]: D/cache2   new storage entries table for context ''
2016-09-26 16:14:21.354806 UTC - [Socket Thread]: V/nsHttp    connection count = 0, limit 6
2016-09-26 16:14:21.354822 UTC - [Socket Thread]: V/nsHttp   result: false
2016-09-26 16:14:21.354843 UTC - [Socket Thread]: V/nsHttp Creating nsHalfOpenSocket [this=7f00ae1b3e20 trans=7f00ac091560 ent=localhost key=......localhost:34047]
2016-09-26 16:14:21.354874 UTC - [Main Thread]: D/cache2 CacheEntry::CacheEntry [this=7f00ac093c00]
2016-09-26 16:14:21.354905 UTC - [Main Thread]: D/cache2 CacheStorageService::RecordMemoryOnlyEntry [entry=7f00ac093c00, memory=0, overwrite=1]
2016-09-26 16:14:21.354932 UTC - [Main Thread]: D/cache2   not recorded as memory only
2016-09-26 16:14:21.354967 UTC - [Main Thread]: D/cache2   new entry 7f00ac093c00 for :http://localhost:34047/content
2016-09-26 16:14:21.354993 UTC - [Main Thread]: D/cache2 New CacheEntryHandle 7f00ac089b80 for entry 7f00ac093c00
2016-09-26 16:14:21.355023 UTC - [Main Thread]: D/cache2 CacheEntry::AsyncOpen [this=7f00ac093c00, state=NOTLOADED, flags=16, callback=7f00adf56520]
2016-09-26 16:14:21.355059 UTC - [Main Thread]: D/cache2 CacheEntry::RememberCallback [this=7f00ac093c00, cb=7f00adf56520, state=NOTLOADED]
2016-09-26 16:14:21.355086 UTC - [Main Thread]: D/cache2 CacheEntry::Load [this=7f00ac093c00, trunc=0]
2016-09-26 16:14:21.355109 UTC - [Main Thread]: D/cache2 CacheIndex::HasEntry() [key=:http://localhost:34047/content]
2016-09-26 16:14:21.355166 UTC - [Main Thread]: D/cache2 CacheIndex::HasEntry() - result is 2
2016-09-26 16:14:21.355209 UTC - [Main Thread]: D/cache2 CacheFile::CacheFile() [this=7f00aece5e00]
2016-09-26 16:14:21.355231 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupStreams [this=7f00ae1b3e20 ent=......localhost:34047] setup routed transport to origin localhost:34047 via :443
2016-09-26 16:14:21.355282 UTC - [Main Thread]: D/cache2 CacheEntry::BackgroundOp this=7f00ac093c00 dipatch of 1
2016-09-26 16:14:21.355310 UTC - [Main Thread]: D/cache2   performing load, file=7f00aece5e00
2016-09-26 16:14:21.355344 UTC - [Main Thread]: D/cache2 CacheFile::Init() [this=7f00aece5e00, key=:http://localhost:34047/content, createNew=0, memoryOnly=0, priority=0, listener=7f00ac093c10]
2016-09-26 16:14:21.355368 UTC - [Cache2 I/O]: D/cache2 CacheEntry REGISTER [this=7f00ac093c00]
2016-09-26 16:14:21.355387 UTC - [Main Thread]: D/cache2 CacheFileIOManager::OpenFile() [key=:http://localhost:34047/content, flags=1, listener=7f00aece5e08]
2016-09-26 16:14:21.355443 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::RegisterEntry [entry=7f00ac093c00]
2016-09-26 16:14:21.355435 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ActivateTimeoutTick() this=7f00b887e1e0 mTimeoutTick=0
2016-09-26 16:14:21.355502 UTC - [Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=7f00ac093c00, state=LOADING, handle=7f00ac089b80]
2016-09-26 16:14:21.355514 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenFileInternal() [hash=84de83046f61656b28c884d89367f2a73f130bdc, key=:http://localhost:34047/content, flags=1]
2016-09-26 16:14:21.355554 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupPrimaryStream [this=7f00ae1b3e20 ent=localhost rv=0]
2016-09-26 16:14:21.355530 UTC - [Main Thread]: D/cache2   not the writer
2016-09-26 16:14:21.355613 UTC - [Cache2 I/O]: D/cache2 CacheFileHandles::GetHandle() hash=84de83046f61656b28c884d89367f2a73f130bdc no handle entries found
2016-09-26 16:14:21.355628 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Connect 7f00adf56000 AwaitingCacheCallbacks forces async
2016-09-26 16:14:21.355662 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult result [this=7f00adf56000 rv=0 mCanceled=0]
2016-09-26 16:14:21.355672 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::CacheFileHandle() [this=7f00ac091680, hash=84de83046f61656b28c884d89367f2a73f130bdc]
2016-09-26 16:14:21.355726 UTC - [Cache2 I/O]: D/cache2 CacheFileHandles::NewHandle() hash=84de83046f61656b28c884d89367f2a73f130bdc created new handle 7f00ac091680, entry=7f00adf71c50
2016-09-26 16:14:21.355750 UTC - [Cache2 I/O]: D/cache2 CacheIndex::AddEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc]
2016-09-26 16:14:21.355777 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.355801 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=0, notInitialized=0, removed=0, dirty=0, fresh=0, empty=0, size=0]
2016-09-26 16:14:21.355830 UTC - [Cache2 I/O]: D/cache2 CacheIndexEntry::CacheIndexEntry() - Created record [rec=7f00ac0ab280]
2016-09-26 16:14:21.355853 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.355865 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupBackupTimer() [this=7f00ae1b3e20], did not arm
2016-09-26 16:14:21.355878 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=1, removed=0, dirty=1, fresh=1, empty=0, size=0]
2016-09-26 16:14:21.356164 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnFileOpened() [this=7f00aece5e00, rv=0x00000000, handle=7f00ac091680]
2016-09-26 16:14:21.356212 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::CacheFileMetadata() [this=7f00b6a85f20, handle=7f00ac091680, key=:http://localhost:34047/content]
2016-09-26 16:14:21.356271 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady [this=7f00ae1b3e20 ent=localhost primary]
2016-09-26 16:14:21.356275 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::ReadMetadata() [this=7f00b6a85f20, listener=7f00aece5e10]
2016-09-26 16:14:21.356335 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick armed=1 active=0
2016-09-26 16:14:21.356367 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick stop==true
2016-09-26 16:14:21.356373 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::ReadMetadata() - Filesize == 0, creating empty metadata. [this=7f00b6a85f20]
2016-09-26 16:14:21.356414 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=240]
2016-09-26 16:14:21.356421 UTC - [Socket Thread]: V/nsHttp Creating nsHttpConnection @7f00aecd13e0
2016-09-26 16:14:21.356439 UTC - [Cache2 I/O]: D/cache2   mMemorySize=240 (+240,-0)
2016-09-26 16:14:21.356475 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady Created new nshttpconnection 7f00aecd13e0
2016-09-26 16:14:21.356526 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Init this=7f00aecd13e0
2016-09-26 16:14:21.356527 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::SetPinned [this=7f00ac091680, pinned=0]
2016-09-26 16:14:21.356582 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnMetadataRead() [this=7f00aece5e00, rv=0x00000000]
2016-09-26 16:14:21.356608 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady no transaction match returning conn 7f00aecd13e0 to pool
2016-09-26 16:14:21.356611 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::InitIndexEntry() [handle=7f00ac091680, appId=0, anonymous=0, inIsolatedMozBrowser=0, pinned=0]
2016-09-26 16:14:21.356685 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgReclaimConnection [conn=7f00aecd1418]
2016-09-26 16:14:21.356705 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::UpdateIndexEntry() [handle=7f00ac091680, frecency=0, expirationTime=4294967295]
2016-09-26 16:14:21.356718 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd13e0 caps=0x401 ......localhost:34047
2016-09-26 16:14:21.356758 UTC - [Cache2 I/O]: D/cache2 CacheEntry::OnFileReady [this=7f00ac093c00, rv=0x00000000, new=1]
2016-09-26 16:14:21.356771 UTC - [Socket Thread]: V/nsHttp   adding connection to idle list
2016-09-26 16:14:21.356778 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.356802 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::BeginIdleMonitoring [this=7f00aecd13e0]
2016-09-26 16:14:21.356820 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.356847 UTC - [Cache2 I/O]: D/cache2   pinning=0
2016-09-26 16:14:21.356850 UTC - [Socket Thread]: V/nsHttp Entering Idle Monitoring Mode [this=7f00aecd13e0]
2016-09-26 16:14:21.356872 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.356904 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::PruneDeadConnectionsAfter
2016-09-26 16:14:21.356961 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeCallback [this=7f00ac093c00, state=EMPTY, cb=7f00adf56520]
2016-09-26 16:14:21.356970 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.356993 UTC - [Cache2 I/O]: D/cache2   advancing to WRITING state
2016-09-26 16:14:21.357032 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.357060 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeAvailableCallback [this=7f00ac093c00, state=WRITING, cb=7f00adf56520, r/o=0, n/w=0]
2016-09-26 16:14:21.357079 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.357098 UTC - [Cache2 I/O]: D/cache2   redispatched, (rv = 0x00000000)
2016-09-26 16:14:21.357103 UTC - [Socket Thread]: V/nsHttp Destroying nsHalfOpenSocket [this=7f00ae1b3e20]
2016-09-26 16:14:21.357156 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.357193 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=5]
2016-09-26 16:14:21.357238 UTC - [Cache2 I/O]: D/cache2 CacheIndex::InitEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, appId=0, anonymous=0, inIsolatedMozBrowser=0, pinned=0]
2016-09-26 16:14:21.357266 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.357291 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=1, removed=0, dirty=1, fresh=1, empty=0, size=0]
2016-09-26 16:14:21.357314 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.357315 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.357347 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.357395 UTC - [Cache2 I/O]: D/cache2 CacheIndex::InsertRecordToFrecencyArray() [record=7f00ac0ab280, hash=84de83046f61656b28c884d89367f2a73f130bdc]
2016-09-26 16:14:21.357457 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=0]
2016-09-26 16:14:21.357464 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.357493 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.357524 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.357537 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.357557 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.357567 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.357599 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.357627 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.357657 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=0, expirationTime=4294967295, size=]
2016-09-26 16:14:21.357673 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.357688 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.357702 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.357716 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.357733 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.384742 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnLookupComplete [this=7f00adf56000] prefetch complete: success status[0x0]
2016-09-26 16:14:21.392157 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeAvailableCallback [this=7f00ac093c00, state=WRITING, cb=7f00adf56520, r/o=0, n/w=0]
2016-09-26 16:14:21.392186 UTC - [Main Thread]: D/cache2 CacheFile::OnFetched() this=7f00aece5e00
2016-09-26 16:14:21.392193 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.392239 UTC - [Main Thread]: D/cache2 CacheEntry::BackgroundOp this=7f00ac093c00 dipatch of 2
2016-09-26 16:14:21.392251 UTC - [Main Thread]: D/cache2 New CacheEntryHandle 7f00b8816660 for entry 7f00ac093c00
2016-09-26 16:14:21.392262 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=7f00adf56000 entry=7f00b8816660 new=1 appcache=0 status=0 mAppCache=0 mAppCacheForWrite=0]
2016-09-26 16:14:21.392272 UTC - [Main Thread]: D/nsHttp nsHttpChannel::SetupTransaction [this=7f00adf56000]
2016-09-26 16:14:21.392300 UTC - [Main Thread]: D/nsHttp Creating nsHttpTransaction @7f00ac09c000
2016-09-26 16:14:21.392311 UTC - [Main Thread]: D/nsHttp nsHttpChannel 7f00adf56000 created nsHttpTransaction 7f00ac09c000
2016-09-26 16:14:21.392319 UTC - [Cache2 I/O]: D/cache2 CacheEntry FRECENCYUPDATE [this=7f00ac093c00, frecency=283979,7931399210]
2016-09-26 16:14:21.392320 UTC - [Main Thread]: D/nsHttp nsHttpTransaction::Init [this=7f00ac09c000 caps=1]
2016-09-26 16:14:21.392388 UTC - [Main Thread]: I/nsHttp http request [
2016-09-26 16:14:21.392406 UTC - [Main Thread]: I/nsHttp   GET /content HTTP/1.1
2016-09-26 16:14:21.392413 UTC - [Main Thread]: I/nsHttp   Host: localhost:34047
2016-09-26 16:14:21.392422 UTC - [Main Thread]: I/nsHttp   User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 /52.0a1
2016-09-26 16:14:21.392430 UTC - [Main Thread]: I/nsHttp   Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2016-09-26 16:14:21.392444 UTC - [Main Thread]: I/nsHttp   Accept-Language: en-US,en;q=0.5
2016-09-26 16:14:21.392451 UTC - [Main Thread]: I/nsHttp   Accept-Encoding: gzip, deflate
2016-09-26 16:14:21.392457 UTC - [Main Thread]: I/nsHttp   Connection: keep-alive
2016-09-26 16:14:21.392463 UTC - [Main Thread]: I/nsHttp ]
2016-09-26 16:14:21.392500 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::AddTransaction [trans=7f00ac09c000 0]
2016-09-26 16:14:21.392557 UTC - [Main Thread]: D/cache2   writing/revalidating
2016-09-26 16:14:21.392578 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgNewTransaction [trans=7f00ac09c028]
2016-09-26 16:14:21.392599 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd13e0 caps=0x401 ......localhost:34047
2016-09-26 16:14:21.392681 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::TryDispatchTransaction without conn [trans=7f00ac09c000 ci=7f00b8878cc0 ci=......localhost:34047 caps=1 tunnelprovider=0 onlyreused=0 active=0 idle=1]
2016-09-26 16:14:21.392703 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd13e0 caps=0x401 ......localhost:34047
2016-09-26 16:14:21.392714 UTC - [Socket Thread]: V/nsHttp    reusing connection [conn=7f00aecd13e0]
2016-09-26 16:14:21.392720 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::EndIdleMonitoring [this=7f00aecd13e0]
2016-09-26 16:14:21.392726 UTC - [Socket Thread]: V/nsHttp Leaving Idle Monitoring Mode [this=7f00aecd13e0]
2016-09-26 16:14:21.392733 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::StopPruneDeadConnectionsTimer
2016-09-26 16:14:21.392750 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ActivateTimeoutTick() this=7f00b887e1e0 mTimeoutTick=7f00ac08b0b0
2016-09-26 16:14:21.392765 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::DispatchTransaction [ent-ci=......localhost:34047 7f00ac08af60 trans=7f00ac09c000 caps=1 conn=7f00aecd13e0 priority=0]
2016-09-26 16:14:21.392774 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::DispatchAbstractTransaction [ci=......localhost:34047 trans=7f00ac09c000 caps=1 conn=7f00aecd13e0]
2016-09-26 16:14:21.392779 UTC - [Socket Thread]: V/nsHttp    not using pipeline datastructure due to class solo.
2016-09-26 16:14:21.392789 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Activate [this=7f00aecd13e0 trans=7f00ac09c000 caps=1]
2016-09-26 16:14:21.392814 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd13e0 caps=0x1 ......localhost:34047
2016-09-26 16:14:21.392825 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::StartShortLivedTCPKeepalives[7f00aecd13e0] idle time[10s].
2016-09-26 16:14:21.392861 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable [this=7f00aecd13e0] host=localhost
2016-09-26 16:14:21.392872 UTC - [Socket Thread]: V/nsHttp   writing transaction request stream
2016-09-26 16:14:21.392881 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::GetSecurityInfo trans=7f00ac09c000 tlsfilter=0 socket=7f00ac09a018
2016-09-26 16:14:21.392923 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=7f00ac09c000 status=804b0005 progress=287]
2016-09-26 16:14:21.392932 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnTransportStatus 7f00ac09c000 SENDING_TO without request body
2016-09-26 16:14:21.392940 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 7f00aecd13e0 ReadSegments returned [rv=0 read=287 sock-cond=0]
2016-09-26 16:14:21.392946 UTC - [Socket Thread]: V/nsHttp   writing transaction request stream
2016-09-26 16:14:21.392954 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketWritable 7f00aecd13e0 ReadSegments returned [rv=0 read=0 sock-cond=0]
2016-09-26 16:14:21.392961 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=7f00ac09c000 status=804b000a progress=0]
2016-09-26 16:14:21.392976 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=7f00aecd13e0]
2016-09-26 16:14:21.393072 UTC - [Socket Thread]: V/nsHttp    dispatched step 2 (idle) trans=7f00ac09c000
2016-09-26 16:14:21.393082 UTC - [Socket Thread]: V/nsHttp   ProcessNewTransaction Dispatch Immediately trans=7f00ac09c000
2016-09-26 16:14:21.395965 UTC - [Main Thread]: D/cache2 CacheFile::SetFrecency() this=7f00aece5e00, frecency=1022327255
2016-09-26 16:14:21.395980 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.396008 UTC - [Main Thread]: D/cache2 CacheFileIOManager::UpdateIndexEntry() [handle=7f00ac091680, frecency=1022327255, expirationTime=]
2016-09-26 16:14:21.396033 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetFrecency() [this=7f00b6a85f20, frecency=1022327255,000000]
2016-09-26 16:14:21.396038 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=1022327255, expirationTime=, size=]
2016-09-26 16:14:21.396062 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.396070 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.396078 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.396085 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.396095 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.466165 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable [this=7f00aecd13e0]
2016-09-26 16:14:21.466186 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 7f00ac09c000 reentrantFlag=0
2016-09-26 16:14:21.466205 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=7f00ac09c000 status=804b0006 progress=169]
2016-09-26 16:14:21.466210 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ProcessData [this=7f00ac09c000 count=169]
2016-09-26 16:14:21.466212 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseHead [count=169]
2016-09-26 16:14:21.466222 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [HTTP/1.1 200 OK]
2016-09-26 16:14:21.466226 UTC - [Socket Thread]: D/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 200 OK]
2016-09-26 16:14:21.466237 UTC - [Socket Thread]: D/nsHttp Have status line [version=11 status=200 statusText=OK]
2016-09-26 16:14:21.466242 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [content-type: text/plain]
2016-09-26 16:14:21.466253 UTC - [Socket Thread]: D/nsHttp ParseContentType [type=text/plain]
2016-09-26 16:14:21.466259 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [cache-control: max-age=86400]
2016-09-26 16:14:21.466267 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [connection: close]
2016-09-26 16:14:21.466274 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [server: httpd.js]
2016-09-26 16:14:21.466282 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [date: Mon, 26 Sep 2016 16:14:21 GMT]
2016-09-26 16:14:21.466289 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ParseLine [content-length: 13]
2016-09-26 16:14:21.466299 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::HandleContent [this=7f00ac09c000 count=0]
2016-09-26 16:14:21.466305 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::HandleContentStart [this=7f00ac09c000]
2016-09-26 16:14:21.466307 UTC - [Socket Thread]: I/nsHttp http response [
2016-09-26 16:14:21.466323 UTC - [Socket Thread]: I/nsHttp   HTTP/1.1 200 OK
2016-09-26 16:14:21.466327 UTC - [Socket Thread]: I/nsHttp   Content-Type: text/plain
2016-09-26 16:14:21.466330 UTC - [Socket Thread]: I/nsHttp   Cache-Control: max-age=86400
2016-09-26 16:14:21.466333 UTC - [Socket Thread]: I/nsHttp   Connection: close
2016-09-26 16:14:21.466336 UTC - [Socket Thread]: I/nsHttp   Server: httpd.js
2016-09-26 16:14:21.466339 UTC - [Socket Thread]: I/nsHttp   Date: Mon, 26 Sep 2016 16:14:21 GMT
2016-09-26 16:14:21.466342 UTC - [Socket Thread]: I/nsHttp   Content-Length: 13
2016-09-26 16:14:21.466344 UTC - [Socket Thread]: I/nsHttp     OriginalHeaders
2016-09-26 16:14:21.466366 UTC - [Socket Thread]: I/nsHttp   Content-Type: text/plain
2016-09-26 16:14:21.466374 UTC - [Socket Thread]: I/nsHttp   Cache-Control: max-age=86400
2016-09-26 16:14:21.466393 UTC - [Socket Thread]: I/nsHttp   Connection: close
2016-09-26 16:14:21.466396 UTC - [Socket Thread]: I/nsHttp   Server: httpd.js
2016-09-26 16:14:21.466399 UTC - [Socket Thread]: I/nsHttp   Date: Mon, 26 Sep 2016 16:14:21 GMT
2016-09-26 16:14:21.466402 UTC - [Socket Thread]: I/nsHttp   Content-Length: 13
2016-09-26 16:14:21.466404 UTC - [Socket Thread]: I/nsHttp ]
2016-09-26 16:14:21.466409 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnHeadersAvailable [this=7f00aecd13e0 trans=7f00ac09c000 response-head=7f00adfe3700]
2016-09-26 16:14:21.466420 UTC - [Socket Thread]: V/nsHttp Assessing red penalty to localhost class 3 for event 131075. Penalty now 0, throttle[3] = 250
2016-09-26 16:14:21.466430 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::HandleContent [this=7f00ac09c000 count=0 read=0 mContentRead=0 mContentLength=13]
2016-09-26 16:14:21.466435 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7f00aecd13e0 trans->ws rv=0 n=0 socketin=0
2016-09-26 16:14:21.466438 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 7f00ac09c000 reentrantFlag=0
2016-09-26 16:14:21.466446 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7f00aecd13e0 trans->ws rv=0 n=0 socketin=80470007
2016-09-26 16:14:21.466449 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=7f00aecd13e0]
2016-09-26 16:14:21.471108 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable [this=7f00aecd13e0]
2016-09-26 16:14:21.471121 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 7f00ac09c000 reentrantFlag=0
2016-09-26 16:14:21.471130 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=7f00ac09c000 status=804b0006 progress=182]
2016-09-26 16:14:21.471134 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::ProcessData [this=7f00ac09c000 count=13]
2016-09-26 16:14:21.471137 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::HandleContent [this=7f00ac09c000 count=13]
2016-09-26 16:14:21.471141 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::HandleContent [this=7f00ac09c000 count=13 read=13 mContentRead=13 mContentLength=13]
2016-09-26 16:14:21.471145 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction 7f00ac09c000 request context set to null in ReleaseBlockingTransaction() - was 0
2016-09-26 16:14:21.471158 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7f00aecd13e0 trans->ws rv=0 n=13 socketin=0
2016-09-26 16:14:21.471162 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::WriteSegments 7f00ac09c000 reentrantFlag=0
2016-09-26 16:14:21.471165 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::OnSocketReadable 7f00aecd13e0 trans->ws rv=80470002 n=13 socketin=0
2016-09-26 16:14:21.471169 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::CloseTransaction[this=7f00aecd13e0 trans=7f00ac09c000 reason=80470002]
2016-09-26 16:14:21.471173 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::Close [this=7f00ac09c000 reason=0]
2016-09-26 16:14:21.471178 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ReclaimConnection [conn=7f00aecd13e0]
2016-09-26 16:14:21.471200 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction 7f00ac09c000 request context set to null in ReleaseBlockingTransaction() - was 0
2016-09-26 16:14:21.471219 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgReclaimConnection [conn=7f00aecd1418]
2016-09-26 16:14:21.471226 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick armed=1 active=0
2016-09-26 16:14:21.471229 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick stop==true
2016-09-26 16:14:21.471237 UTC - [Socket Thread]: V/nsHttp   connection cannot be reused; closing connection
2016-09-26 16:14:21.471241 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Close [this=7f00aecd13e0 reason=80004004]
2016-09-26 16:14:21.471248 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Close drained 0 bytes
2016-09-26 16:14:21.471282 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.471288 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=0 queued=0]
2016-09-26 16:14:21.471309 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=0 queued=0]
2016-09-26 16:14:21.471313 UTC - [Socket Thread]: V/nsHttp Destroying nsHttpConnection @7f00aecd13e0
2016-09-26 16:14:21.471316 UTC - [Socket Thread]: V/nsHttp nsHttpConnection 7f00aecd13e0 performed 1 HTTP/1.x transactions
2016-09-26 16:14:21.471384 UTC - [Socket Thread]: V/nsHttp nsHttpConnection 7f00aecd13e0 read 0kb on connection spdy=0
2016-09-26 16:14:21.472693 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=7f00adf56000 request=7f00adf71e00 status=0]
2016-09-26 16:14:21.472708 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ProcessResponse [this=7f00adf56000 httpStatus=200]
2016-09-26 16:14:21.472720 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adf56058 event="http-on-examine-response"]
2016-09-26 16:14:21.472735 UTC - [Main Thread]: D/nsHttp nsHttpChannelAuthProvider::CheckForSuperfluousAuth? [this=7f00ac093200 channel=7f00adf56538]
2016-09-26 16:14:21.472744 UTC - [Main Thread]: D/nsHttp   continuation state has been reset
2016-09-26 16:14:21.472750 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ProcessNormal [this=7f00adf56000]
2016-09-26 16:14:21.472759 UTC - [Main Thread]: D/nsHttp nsHttpChannel::InitCacheEntry [this=7f00adf56000 entry=7f00b8816660]
2016-09-26 16:14:21.472765 UTC - [Main Thread]: D/nsHttp nsHttpResponseHead::MustValidate ??
2016-09-26 16:14:21.472771 UTC - [Main Thread]: D/nsHttp no mandatory validation requirement
2016-09-26 16:14:21.472785 UTC - [Main Thread]: D/nsHttp freshnessLifetime = 86400, currentAge = 0
2016-09-26 16:14:21.472794 UTC - [Main Thread]: D/cache2 CacheFile::SetExpirationTime() this=7f00aece5e00, expiration=1474992861
2016-09-26 16:14:21.472799 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.472822 UTC - [Main Thread]: D/cache2 CacheFileIOManager::UpdateIndexEntry() [handle=7f00ac091680, frecency=, expirationTime=1474992861]
2016-09-26 16:14:21.472863 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetExpirationTime() [this=7f00b6a85f20, expirationTime=1474992861]
2016-09-26 16:14:21.472872 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.472878 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.472878 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=1474992861, size=]
2016-09-26 16:14:21.472912 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=strongly-framed, value=7f00cc5a6ebf]
2016-09-26 16:14:21.472920 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=strongly-framed]
2016-09-26 16:14:21.472916 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.472928 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=304]
2016-09-26 16:14:21.472934 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.472942 UTC - [Main Thread]: D/cache2   mMemorySize=304 (+304,-240)
2016-09-26 16:14:21.472952 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.472959 UTC - [Main Thread]: D/nsHttp nsHttpChannel::AddCacheEntryHeaders [this=7f00adf56000] begin
2016-09-26 16:14:21.472971 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.472964 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.472977 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.472994 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.472997 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=request-method, value=7f00cc5abf31]
2016-09-26 16:14:21.473009 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=request-method]
2016-09-26 16:14:21.473043 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.473048 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.473062 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=response-head, value=7f00ac0b5378]
2016-09-26 16:14:21.473068 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=response-head]
2016-09-26 16:14:21.473074 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=496]
2016-09-26 16:14:21.473078 UTC - [Main Thread]: D/cache2   mMemorySize=496 (+496,-304)
2016-09-26 16:14:21.473092 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.473097 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.473111 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=original-response-headers, value=7f00ac0b5378]
2016-09-26 16:14:21.473133 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=original-response-headers]
2016-09-26 16:14:21.473139 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=752]
2016-09-26 16:14:21.473143 UTC - [Main Thread]: D/cache2   mMemorySize=752 (+752,-496)
2016-09-26 16:14:21.473150 UTC - [Main Thread]: D/cache2 CacheEntry::MetaDataReady [this=7f00ac093c00, state=WRITING]
2016-09-26 16:14:21.473155 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.473160 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.473170 UTC - [Main Thread]: D/nsHttp   calling mListener->OnStartRequest
2016-09-26 16:14:21.475152 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::DoApplyContentConversions [this=7f00adf56000]
2016-09-26 16:14:21.475165 UTC - [Main Thread]: D/nsHttp Preparing to write data into the cache [uri=http://localhost:34047/content]
2016-09-26 16:14:21.475174 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.475179 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.475196 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=uncompressed-len, value=7f00cc5a6ebf]
2016-09-26 16:14:21.475203 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=uncompressed-len]
2016-09-26 16:14:21.475209 UTC - [Main Thread]: D/nsHttp Trading cache input stream for output stream [channel=7f00adf56000]
2016-09-26 16:14:21.475215 UTC - [Main Thread]: D/cache2 CacheEntry::OpenOutputStream [this=7f00ac093c00]
2016-09-26 16:14:21.475220 UTC - [Main Thread]: D/cache2 CacheEntry::OpenOutputStreamInternal [this=7f00ac093c00]
2016-09-26 16:14:21.475232 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::CacheFileOutputStream() [this=7f00ac08afd0]
2016-09-26 16:14:21.475238 UTC - [Main Thread]: D/cache2 CacheFile::OpenOutputStream() - Creating new output stream 7f00ac08afd0 [this=7f00aece5e00]
2016-09-26 16:14:21.475248 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Seek() [this=7f00ac08afd0, whence=0, offset=0]
2016-09-26 16:14:21.475254 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08afd0, releaseOnly=1]
2016-09-26 16:14:21.475259 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Seek() [this=7f00ac08afd0, pos=0]
2016-09-26 16:14:21.475268 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.475274 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.475288 UTC - [Main Thread]: D/nsHttp nsHttpChannel::InstallCacheListener sync tee 7f00ac0c4ce0 rv=0 cacheIOTarget=0
2016-09-26 16:14:21.475305 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=7f00adf56000 request=7f00adf71e00 offset=0 count=13]
2016-09-26 16:14:21.475866 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() [this=7f00ac08afd0, count=13]
2016-09-26 16:14:21.475875 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08afd0, releaseOnly=0]
2016-09-26 16:14:21.475880 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=0, caller=1, listener=0]
2016-09-26 16:14:21.475888 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0cd980, index=0, initByWriter=1]
2016-09-26 16:14:21.475896 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Created new empty chunk 7f00ac0cd980 [this=7f00aece5e00]
2016-09-26 16:14:21.475901 UTC - [Main Thread]: D/cache2 CacheFileChunk::InitNew() [this=7f00ac0cd980]
2016-09-26 16:14:21.475908 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=0, hash=d10d]
2016-09-26 16:14:21.475914 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=754]
2016-09-26 16:14:21.475919 UTC - [Main Thread]: D/cache2   mMemorySize=754 (+754,-752)
2016-09-26 16:14:21.475925 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0cd980, ensuredBufSize=13]
2016-09-26 16:14:21.475930 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cd980, size=512]
2016-09-26 16:14:21.475936 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 512 [this=7f00ac0cd980]
2016-09-26 16:14:21.475943 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0cd980, offset=0, len=13]
2016-09-26 16:14:21.475947 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cd980]
2016-09-26 16:14:21.475953 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08afd0, releaseOnly=1]
2016-09-26 16:14:21.475958 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08afd0, idx=0]
2016-09-26 16:14:21.475963 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() - Wrote 13 bytes [this=7f00ac08afd0]
2016-09-26 16:14:21.476156 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=7f00adf56000 request=7f00adf71e00 status=0]
2016-09-26 16:14:21.476164 UTC - [Main Thread]: D/nsHttp   dropping upload stream
2016-09-26 16:14:21.476170 UTC - [Main Thread]: D/nsHttp nsHttpChannel 7f00adf56000 has a strongly framed transaction: 1
2016-09-26 16:14:21.476176 UTC - [Main Thread]: D/nsHttp nsHttpTransaction::DeleteSelfOnConsumerThread [this=7f00ac09c000]
2016-09-26 16:14:21.476181 UTC - [Main Thread]: D/nsHttp Destroying nsHttpTransaction @7f00ac09c000
2016-09-26 16:14:21.476187 UTC - [Main Thread]: D/nsHttp nsHttpTransaction 7f00ac09c000 request context set to null in ReleaseBlockingTransaction() - was 0
2016-09-26 16:14:21.476205 UTC - [Main Thread]: D/nsHttp nsHttpChannel::FinalizeCacheEntry [this=7f00adf56000]
2016-09-26 16:14:21.476210 UTC - [Main Thread]: D/nsHttp nsHttpChannel::FinalizeCacheEntry [this=7f00adf56000] Is Strongly Framed
2016-09-26 16:14:21.476216 UTC - [Main Thread]: D/cache2 CacheFile::SetElement() this=7f00aece5e00
2016-09-26 16:14:21.476220 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.476236 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=strongly-framed, value=7f00cc5a0623]
2016-09-26 16:14:21.476242 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=strongly-framed]
2016-09-26 16:14:21.476252 UTC - [Main Thread]: D/nsHttp   calling OnStopRequest
2016-09-26 16:14:21.476260 UTC - [Main Thread]: D/cache2 CacheFile::RemoveOutput() [this=7f00aece5e00, output=7f00ac08afd0, status=0x00000000]
2016-09-26 16:14:21.476264 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() [this=7f00aece5e00]
2016-09-26 16:14:21.476270 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() - fail2 [this=7f00aece5e00, idx=0]
2016-09-26 16:14:21.476275 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cd980]
2016-09-26 16:14:21.476281 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.476324 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::~CacheFileOutputStream() [this=7f00ac08afd0]
2016-09-26 16:14:21.476333 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cd980, idx=0]
2016-09-26 16:14:21.476341 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.476347 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0cd980, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.476355 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=0, count=13, validate=0, truncate=0, listener=7f00ac0cd980]
2016-09-26 16:14:21.476372 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=0, count=13, validate=0, truncate=0]
2016-09-26 16:14:21.476398 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle BEGIN, handle=7f00ac091680
2016-09-26 16:14:21.476426 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle END, handle=7f00ac091680
2016-09-26 16:14:21.476533 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=1]
2016-09-26 16:14:21.476539 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.476543 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=1, size=0]
2016-09-26 16:14:21.476547 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.476551 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=1]
2016-09-26 16:14:21.476554 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.476604 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.476609 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.476612 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.476615 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 1
2016-09-26 16:14:21.476620 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=1kB, cacheSizeLimit=256000kB, freeSpace=106633314304, freeSpaceLimit=5242880]
2016-09-26 16:14:21.476625 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0cd980, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.476641 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cd980, idx=0]
2016-09-26 16:14:21.476646 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=0, hash=43b9]
2016-09-26 16:14:21.476669 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=754]
2016-09-26 16:14:21.476673 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0cd980]
2016-09-26 16:14:21.476684 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.476714 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() - Writing metadata [this=7f00aece5e00]
2016-09-26 16:14:21.476719 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::WriteMetadata() [this=7f00b6a85f20, offset=13, listener=7f00aece5e10]
2016-09-26 16:14:21.476726 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=13, count=470, validate=1, truncate=1, listener=7f00b6a85f20]
2016-09-26 16:14:21.476734 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=754]
2016-09-26 16:14:21.476742 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.476757 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=13, count=470, validate=1, truncate=1]
2016-09-26 16:14:21.476844 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::OnDataWritten() [this=7f00b6a85f20, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.476849 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() [this=7f00aece5e00, rv=0x00000000]
2016-09-26 16:14:21.476852 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() - Releasing file handle [this=7f00aece5e00]
2016-09-26 16:14:21.476856 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandle() [handle=7f00ac091680]
2016-09-26 16:14:21.476865 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=754]
2016-09-26 16:14:21.476869 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.476874 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::MaybeReleaseNSPRHandleInternal() [handle=7f00ac091680, ignore shutdown=0]
2016-09-26 16:14:21.476879 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::MaybeReleaseNSPRHandleInternal() DONE
2016-09-26 16:14:21.476883 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.494439 UTC - [Main Thread]: D/nsHttp nsHttpChannel::CloseCacheEntry [this=7f00adf56000] mStatus=0 mCacheEntryIsWriteOnly=1
2016-09-26 16:14:21.568888 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.568955 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.569231 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0cd980]
2016-09-26 16:14:21.569267 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 0 [this=7f00ac0cd980]
2016-09-26 16:14:21.570204 UTC - [Main Thread]: D/cache2 CacheEntry::OpenAlternativeOutputStream [this=7f00ac093c00, type=text/binary]
2016-09-26 16:14:21.570259 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetElement() [this=7f00b6a85f20, key=alt-data, value=7ffd1b363240]
2016-09-26 16:14:21.570274 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=alt-data]
2016-09-26 16:14:21.570289 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::CacheFileOutputStream() [this=7f00ac08b2e0]
2016-09-26 16:14:21.570302 UTC - [Main Thread]: D/cache2 CacheFile::OpenAlternativeOutputStream() - Creating new output stream 7f00ac08b2e0 [this=7f00aece5e00]
2016-09-26 16:14:21.585854 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() [this=7f00ac08b2e0, count=262147]
2016-09-26 16:14:21.585872 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.585879 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=0, caller=1, listener=0]
2016-09-26 16:14:21.585890 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0cd980, index=0, initByWriter=1]
2016-09-26 16:14:21.585898 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Reading newly created chunk 7f00ac0cd980 from the disk [this=7f00aece5e00]
2016-09-26 16:14:21.585905 UTC - [Main Thread]: D/cache2 CacheFileChunk::Read() [this=7f00ac0cd980, handle=7f00ac091680, len=13, listener=7f00aece5e00]
2016-09-26 16:14:21.585920 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cd980, size=512]
2016-09-26 16:14:21.585928 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 512 [this=7f00ac0cd980]
2016-09-26 16:14:21.585934 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Read() [handle=7f00ac091680, offset=0, count=13, listener=7f00ac0cd980]
2016-09-26 16:14:21.585961 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0cd980, ensuredBufSize=262144]
2016-09-26 16:14:21.585969 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cd980, size=262144]
2016-09-26 16:14:21.586004 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::ReadInternal() [handle=7f00ac091680, offset=0, count=13]
2016-09-26 16:14:21.586024 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle BEGIN, handle=7f00ac091680
2016-09-26 16:14:21.586045 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::OpenNSPRHandle END, handle=7f00ac091680
2016-09-26 16:14:21.586057 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataRead() [this=7f00ac0cd980, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.586090 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 262656 [this=7f00ac0cd980]
2016-09-26 16:14:21.586114 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0cd980, offset=13, len=262131]
2016-09-26 16:14:21.586123 UTC - [Main Thread]: D/cache2 ValidityMap::Log() - number of pairs: 1
2016-09-26 16:14:21.586128 UTC - [Main Thread]: D/cache2     (13, 262131)
2016-09-26 16:14:21.586133 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.586138 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::ReleaseChunk() [this=7f00ac08b2e0, idx=0]
2016-09-26 16:14:21.586145 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=1, caller=1, listener=0]
2016-09-26 16:14:21.586152 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0cdbc0, index=1, initByWriter=1]
2016-09-26 16:14:21.586159 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Created new empty chunk 7f00ac0cdbc0 [this=7f00aece5e00]
2016-09-26 16:14:21.586163 UTC - [Main Thread]: D/cache2 CacheFileChunk::InitNew() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.586171 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=1, hash=d10d]
2016-09-26 16:14:21.586178 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=756]
2016-09-26 16:14:21.586183 UTC - [Main Thread]: D/cache2   mMemorySize=756 (+756,-754)
2016-09-26 16:14:21.586189 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0cdbc0, ensuredBufSize=16]
2016-09-26 16:14:21.586194 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cdbc0, size=512]
2016-09-26 16:14:21.586200 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 263168 [this=7f00ac0cdbc0]
2016-09-26 16:14:21.586206 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0cdbc0, offset=0, len=16]
2016-09-26 16:14:21.586212 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.586218 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=1]
2016-09-26 16:14:21.586223 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08b2e0, idx=1]
2016-09-26 16:14:21.586228 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() - Wrote 262147 bytes [this=7f00ac08b2e0]
2016-09-26 16:14:21.586279 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataRead() - Merging buffers. [this=7f00ac0cd980]
2016-09-26 16:14:21.586296 UTC - [Cache2 I/O]: D/cache2 ValidityMap::Log() - number of pairs: 1
2016-09-26 16:14:21.586307 UTC - [Cache2 I/O]: D/cache2     (13, 262131)
2016-09-26 16:14:21.586318 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 262656 [this=7f00ac0cd980]
2016-09-26 16:14:21.586328 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkRead() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cd980, idx=0]
2016-09-26 16:14:21.586350 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.592393 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cd980, idx=0]
2016-09-26 16:14:21.592412 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.592418 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0cd980, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.592425 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=0, count=262144, validate=0, truncate=0, listener=7f00ac0cd980]
2016-09-26 16:14:21.592476 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=0, count=262144, validate=0, truncate=0]
2016-09-26 16:14:21.592785 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=256]
2016-09-26 16:14:21.592798 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.592804 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=1]
2016-09-26 16:14:21.592809 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.592814 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=256]
2016-09-26 16:14:21.592819 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.592898 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.592905 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.592909 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.592913 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 256
2016-09-26 16:14:21.592920 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=256kB, cacheSizeLimit=256000kB, freeSpace=106633056256, freeSpaceLimit=5242880]
2016-09-26 16:14:21.592926 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0cd980, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.592934 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cd980, idx=0]
2016-09-26 16:14:21.593460 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NewProxiedChannel [proxyInfo=0]
2016-09-26 16:14:21.593487 UTC - [Main Thread]: V/nsHttp Creating HttpBaseChannel @adfc4800
2016-09-26 16:14:21.593501 UTC - [Main Thread]: D/nsHttp Creating nsHttpChannel [this=7f00adfc4800]
2016-09-26 16:14:21.593524 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::Init [this=7f00adfc4800]
2016-09-26 16:14:21.593531 UTC - [Main Thread]: V/nsHttp host=localhost port=34047
2016-09-26 16:14:21.593535 UTC - [Main Thread]: V/nsHttp uri=http://localhost:34047/content
2016-09-26 16:14:21.593550 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Init [this=7f00adfc4800]
2016-09-26 16:14:21.593975 UTC - [Main Thread]: D/nsHttp nsHttpChannel::AsyncOpen [this=7f00adfc4800]
2016-09-26 16:14:21.593996 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=0, hash=3e1a]
2016-09-26 16:14:21.594002 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=756]
2016-09-26 16:14:21.594009 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0cd980]
2016-09-26 16:14:21.594026 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.594043 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.594057 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::SetRequestHeader [this=7f00adfc4800 header="Cookie" value="" merge=0]
2016-09-26 16:14:21.594072 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adfc4858 event="http-on-opening-request"]
2016-09-26 16:14:21.594084 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ResolveProxy [this=7f00adfc4800]
2016-09-26 16:14:21.594149 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnProxyAvailable [this=7f00adfc4800 pi=0 status=0 mStatus=0]
2016-09-26 16:14:21.594158 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=7f00adfc4800]
2016-09-26 16:14:21.594163 UTC - [Main Thread]: D/nsHttp host=localhost port=34047
2016-09-26 16:14:21.594167 UTC - [Main Thread]: D/nsHttp uri=http://localhost:34047/content
2016-09-26 16:14:21.594184 UTC - [Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7f00b887e1e8 http:localhost:34047:.
2016-09-26 16:14:21.594192 UTC - [Main Thread]: D/nsHttp AltSvcCache::LookupMapping 7f00b887e1e8 MISS
2016-09-26 16:14:21.594197 UTC - [Main Thread]: D/nsHttp AltSvcCache::GetAltServiceMapping 7f00b887e1e8 key=http:localhost:34047:. existing=0 validated=0 ttl=0
2016-09-26 16:14:21.594202 UTC - [Main Thread]: D/nsHttp nsHttpChannel 7f00adfc4800 Using default connection info
2016-09-26 16:14:21.594207 UTC - [Main Thread]: V/nsHttp Init nsHttpConnectionInfo @7f00b8879040
2016-09-26 16:14:21.594240 UTC - [Main Thread]: D/nsHttp nsHttpChannelAuthProvider::AddAuthorizationHeaders? [this=7f00ac094800 channel=7f00adfc4d38]
2016-09-26 16:14:21.594256 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::GetAuthEntryForPath [key=http://localhost:34047 path=/]
2016-09-26 16:14:21.594264 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adfc4858 event="http-on-modify-request"]
2016-09-26 16:14:21.594283 UTC - [Main Thread]: D/nsHttp nsHttpChannel::BeginConnect [this=7f00adfc4800] prefetching
2016-09-26 16:14:21.594325 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult [this=7f00adfc4800]
2016-09-26 16:14:21.594333 UTC - [Main Thread]: D/nsHttp nsHttpChannel::Connect [this=7f00adfc4800]
2016-09-26 16:14:21.594378 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::SpeculativeConnect [ci=......localhost:34047]
2016-09-26 16:14:21.594415 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OpenCacheEntry [this=7f00adfc4800]
2016-09-26 16:14:21.594447 UTC - [Main Thread]: D/cache2 CacheStorageService::AddStorageEntry [entryKey=:http://localhost:34047/content, contextKey=]
2016-09-26 16:14:21.594457 UTC - [Main Thread]: D/cache2 New CacheEntryHandle 7f00ac0c7200 for entry 7f00ac093c00
2016-09-26 16:14:21.594461 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgSpeculativeConnect [ci=......localhost:34047]
2016-09-26 16:14:21.594465 UTC - [Main Thread]: D/cache2 CacheEntry::AsyncOpen [this=7f00ac093c00, state=READY, flags=16, callback=7f00adfc4d20]
2016-09-26 16:14:21.594488 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::AtActiveConnectionLimit [ci=......localhost:34047 caps=401]
2016-09-26 16:14:21.594516 UTC - [Socket Thread]: V/nsHttp    connection count = 0, limit 6
2016-09-26 16:14:21.594520 UTC - [Socket Thread]: V/nsHttp   result: false
2016-09-26 16:14:21.594505 UTC - [Main Thread]: D/cache2 CacheEntry::RememberCallback [this=7f00ac093c00, cb=7f00adfc4d20, state=READY]
2016-09-26 16:14:21.594539 UTC - [Main Thread]: D/cache2 CacheEntry::Load [this=7f00ac093c00, trunc=0]
2016-09-26 16:14:21.594544 UTC - [Main Thread]: D/cache2   already loaded
2016-09-26 16:14:21.594529 UTC - [Socket Thread]: V/nsHttp Creating nsHalfOpenSocket [this=7f00ac0c17a0 trans=7f00ae1bf920 ent=localhost key=......localhost:34047]
2016-09-26 16:14:21.594549 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.594568 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallback [this=7f00ac093c00, state=READY, cb=7f00adfc4d20]
2016-09-26 16:14:21.594574 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupStreams [this=7f00ac0c17a0 ent=......localhost:34047] setup routed transport to origin localhost:34047 via :443
2016-09-26 16:14:21.594580 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryCheck enter [channel=7f00adfc4800 entry=7f00ac093c00]
2016-09-26 16:14:21.594593 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=request-method]
2016-09-26 16:14:21.594605 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=original-response-headers]
2016-09-26 16:14:21.594611 UTC - [Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedOriginalHeader [this=7f00a8a0b580]
2016-09-26 16:14:21.594623 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ActivateTimeoutTick() this=7f00b887e1e0 mTimeoutTick=7f00ac08b0b0
2016-09-26 16:14:21.594641 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=response-head]
2016-09-26 16:14:21.594643 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupPrimaryStream [this=7f00ac0c17a0 ent=localhost rv=0]
2016-09-26 16:14:21.594649 UTC - [Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedHead [this=7f00a8a0b580]
2016-09-26 16:14:21.594657 UTC - [Main Thread]: D/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 200 OK
Content-Type: text/plain
Cache-Control: max-age=86400
Server: httpd.js
Date: Mon, 26 Sep 2016 16:14:21 GMT
Content-Length: 13
]
2016-09-26 16:14:21.594664 UTC - [Main Thread]: D/nsHttp Have status line [version=11 status=200 statusText=OK]
2016-09-26 16:14:21.594672 UTC - [Main Thread]: D/nsHttp ParseContentType [type=text/plain]
2016-09-26 16:14:21.594692 UTC - [Main Thread]: D/cache2 CacheEntry::GetDataSize [this=7f00ac093c00]
2016-09-26 16:14:21.594699 UTC - [Main Thread]: D/cache2   size=13
2016-09-26 16:14:21.594704 UTC - [Main Thread]: D/nsHttp ### CheckPartial rv=0, size=13, contentLength=13
2016-09-26 16:14:21.594712 UTC - [Main Thread]: D/cache2 CacheEntry::GetIsForcedValid [this=7f00ac093c00, IsForcedValid=0]
2016-09-26 16:14:21.594717 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=strongly-framed]
2016-09-26 16:14:21.594724 UTC - [Main Thread]: D/nsHttp nsHttpResponseHead::MustValidate ??
2016-09-26 16:14:21.594728 UTC - [Main Thread]: D/nsHttp no mandatory validation requirement
2016-09-26 16:14:21.594738 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::SetupBackupTimer() [this=7f00ac0c17a0], did not arm
2016-09-26 16:14:21.594740 UTC - [Main Thread]: D/nsHttp   NowInSeconds()=1474906461, expiration time=1474992861, freshness lifetime=86400, age=0
2016-09-26 16:14:21.594749 UTC - [Main Thread]: D/nsHttp   not validating, expire time not in the past
2016-09-26 16:14:21.594754 UTC - [Main Thread]: D/nsHttp Not validating based on expiration time
2016-09-26 16:14:21.594760 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key not found [this=7f00b6a85f20, key=auth]
2016-09-26 16:14:21.594767 UTC - [Main Thread]: D/cache2 CacheEntry::OpenAlternativeInputStream [this=7f00ac093c00, type=text/binary]
2016-09-26 16:14:21.594771 UTC - [Main Thread]: D/cache2 CacheEntry::OpenInputStreamInternal [this=7f00ac093c00]
2016-09-26 16:14:21.594776 UTC - [Main Thread]: D/cache2 New CacheEntryHandle 7f00ac0c7800 for entry 7f00ac093c00
2016-09-26 16:14:21.594782 UTC - [Main Thread]: D/cache2 CacheFileMetadata::GetElement() - Key found [this=7f00b6a85f20, key=alt-data]
2016-09-26 16:14:21.594793 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CacheFileInputStream() [this=7f00ac08be40]
2016-09-26 16:14:21.594799 UTC - [Main Thread]: D/cache2 CacheFile::OpenAlternativeInputStream() - Creating new input stream 7f00ac08be40 [this=7f00aece5e00]
2016-09-26 16:14:21.594808 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Seek() [this=7f00ac08be40, whence=0, offset=0]
2016-09-26 16:14:21.594813 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.594823 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=0, caller=0, listener=7f00ac08be50]
2016-09-26 16:14:21.594830 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0cde90, index=0, initByWriter=0]
2016-09-26 16:14:21.594836 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Reading newly created chunk 7f00ac0cde90 from the disk [this=7f00aece5e00]
2016-09-26 16:14:21.594840 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady [this=7f00ac0c17a0 ent=localhost primary]
2016-09-26 16:14:21.594851 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick armed=1 active=0
2016-09-26 16:14:21.594842 UTC - [Main Thread]: D/cache2 CacheFileChunk::Read() [this=7f00ac0cde90, handle=7f00ac091680, len=262144, listener=7f00aece5e00]
2016-09-26 16:14:21.594857 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ConditionallyStopTimeoutTick stop==true
2016-09-26 16:14:21.594877 UTC - [Socket Thread]: V/nsHttp Creating nsHttpConnection @7f00aecd0200
2016-09-26 16:14:21.594883 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady Created new nshttpconnection 7f00aecd0200
2016-09-26 16:14:21.594889 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Init this=7f00aecd0200
2016-09-26 16:14:21.594906 UTC - [Socket Thread]: V/nsHttp nsHalfOpenSocket::OnOutputStreamReady no transaction match returning conn 7f00aecd0200 to pool
2016-09-26 16:14:21.594913 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgReclaimConnection [conn=7f00aecd0238]
2016-09-26 16:14:21.594919 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd0200 caps=0x401 ......localhost:34047
2016-09-26 16:14:21.594926 UTC - [Socket Thread]: V/nsHttp   adding connection to idle list
2016-09-26 16:14:21.594932 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::BeginIdleMonitoring [this=7f00aecd0200]
2016-09-26 16:14:21.594936 UTC - [Socket Thread]: V/nsHttp Entering Idle Monitoring Mode [this=7f00aecd0200]
2016-09-26 16:14:21.594942 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::PruneDeadConnectionsAfter
2016-09-26 16:14:21.594958 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Read() [handle=7f00ac091680, offset=0, count=262144, listener=7f00ac0cde90]
2016-09-26 16:14:21.594960 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.594974 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.594981 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.594981 UTC - [Main Thread]: D/cache2 CacheFile::QueueChunkListener() [this=7f00aece5e00, idx=0, listener=7f00ac08be50]
2016-09-26 16:14:21.594992 UTC - [Socket Thread]: V/nsHttp Destroying nsHalfOpenSocket [this=7f00ac0c17a0]
2016-09-26 16:14:21.594997 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=0, mListeningForChunk=0, mWaitingForUpdate=0]
2016-09-26 16:14:21.595003 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Seek() [this=7f00ac08be40, pos=13]
2016-09-26 16:14:21.595003 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.595014 UTC - [Main Thread]: D/cache2 CacheEntry::GetAltDataSize [this=7f00ac093c00]
2016-09-26 16:14:21.595008 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::ReadInternal() [handle=7f00ac091680, offset=0, count=262144]
2016-09-26 16:14:21.595023 UTC - [Main Thread]: D/nsHttp Opened cache input stream without buffering [channel=7f00adfc4800, mCacheEntry=7f00ac093c00, stream=7f00ac08be40]
2016-09-26 16:14:21.595039 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgProcessPendingQ [ci=......localhost:34047]
2016-09-26 16:14:21.595044 UTC - [Main Thread]: D/nsHttp nsHTTPChannel::OnCacheEntryCheck exit [this=7f00adfc4800 doValidation=0 result=0]
2016-09-26 16:14:21.595054 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.595062 UTC - [Main Thread]: D/cache2   OnCacheEntryCheck: rv=0x00000000, result=0
2016-09-26 16:14:21.595072 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=......localhost:34047 ent=7f00ac08af60 active=0 idle=1 queued=0]
2016-09-26 16:14:21.595079 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeAvailableCallback [this=7f00ac093c00, state=READY, cb=7f00adfc4d20, r/o=0, n/w=0]
2016-09-26 16:14:21.595086 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataRead() [this=7f00ac0cde90, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.595088 UTC - [Main Thread]: D/cache2   ready/has-meta, notifying OCEA with entry and NS_OK
2016-09-26 16:14:21.595104 UTC - [Main Thread]: D/cache2 CacheEntry::BackgroundOp this=7f00ac093c00 dipatch of 2
2016-09-26 16:14:21.596091 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkRead() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cde90, idx=0]
2016-09-26 16:14:21.596100 UTC - [Cache2 I/O]: D/cache2 CacheFile::NotifyChunkListeners() [this=7f00aece5e00, idx=0, rv=0x00000000, chunk=7f00ac0cde90]
2016-09-26 16:14:21.596107 UTC - [Cache2 I/O]: D/cache2 CacheFile::NotifyChunkListener() [this=7f00aece5e00, listener=7f00ac08be50, target=7f00b8883ce0, rv=0x00000000, idx=0, chunk=7f00ac0cde90]
2016-09-26 16:14:21.596112 UTC - [Cache2 I/O]: D/cache2 NotifyChunkListenerEvent::NotifyChunkListenerEvent() [this=7f00ac0ed730]
2016-09-26 16:14:21.596126 UTC - [Main Thread]: D/cache2 CacheFile::OnFetched() this=7f00aece5e00
2016-09-26 16:14:21.596130 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.596131 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.596139 UTC - [Cache2 I/O]: D/cache2 NotifyChunkListenerEvent::Run() [this=7f00ac0ed730]
2016-09-26 16:14:21.596150 UTC - [Main Thread]: D/cache2 New CacheEntryHandle 7f00ac0c7f80 for entry 7f00ac093c00
2016-09-26 16:14:21.596157 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=7f00adfc4800 entry=7f00ac0c7f80 new=0 appcache=0 status=0 mAppCache=0 mAppCacheForWrite=0]
2016-09-26 16:14:21.596165 UTC - [Main Thread]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.596157 UTC - [Cache2 I/O]: D/cache2 CacheFileInputStream::OnChunkAvailable() [this=7f00ac08be40, result=0x00000000, idx=0, chunk=7f00ac0cde90]
2016-09-26 16:14:21.596171 UTC - [Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=7f00ac093c00, state=READY, handle=7f00ac0c7200]
2016-09-26 16:14:21.596179 UTC - [Cache2 I/O]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0cde90, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.596180 UTC - [Main Thread]: D/cache2   not the writer
2016-09-26 16:14:21.596189 UTC - [Cache2 I/O]: D/cache2 NotifyChunkListenerEvent::~NotifyChunkListenerEvent() [this=7f00ac0ed730]
2016-09-26 16:14:21.596196 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ReadFromCache [this=7f00adfc4800] Using cached copy of: http://localhost:34047/content
2016-09-26 16:14:21.596214 UTC - [Main Thread]: D/cache2 CacheFileInputStream::AsyncWait() [this=7f00ac08be40, callback=7f00adf0c308, flags=0, requestedCount=0, eventTarget=7f00b8881150]
2016-09-26 16:14:21.596221 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.596222 UTC - [Cache2 I/O]: D/cache2 CacheEntry FRECENCYUPDATE [this=7f00ac093c00, frecency=283980,4863067332]
2016-09-26 16:14:21.596226 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=0]
2016-09-26 16:14:21.596234 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=7f00adf0c308, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0cde90, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.596241 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cde90]
2016-09-26 16:14:21.596246 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262131]
2016-09-26 16:14:21.596249 UTC - [Main Thread]: D/cache2 CacheFileInputStream::NotifyListener() [this=7f00ac08be40]
2016-09-26 16:14:21.596294 UTC - [Main Thread]: D/nsHttp nsHttpChannel::ContinueBeginConnectWithResult result [this=7f00adfc4800 rv=0 mCanceled=0]
2016-09-26 16:14:21.598112 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0cd980]
2016-09-26 16:14:21.598140 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 512 [this=7f00ac0cd980]
2016-09-26 16:14:21.598194 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnLookupComplete [this=7f00adfc4800] prefetch complete: success status[0x0]
2016-09-26 16:14:21.600993 UTC - [Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=adfc4858 event="http-on-examine-cached-response"]
2016-09-26 16:14:21.601077 UTC - [Main Thread]: D/cache2 CacheFile::SetFrecency() this=7f00aece5e00, frecency=1022329750
2016-09-26 16:14:21.601085 UTC - [Main Thread]: D/cache2 CacheFile::PostWriteTimer() [this=7f00aece5e00]
2016-09-26 16:14:21.601102 UTC - [Main Thread]: D/cache2 CacheFileIOManager::UpdateIndexEntry() [handle=7f00ac091680, frecency=1022329750, expirationTime=]
2016-09-26 16:14:21.601115 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetFrecency() [this=7f00b6a85f20, frecency=1022329750,000000]
2016-09-26 16:14:21.601150 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=1022329750, expirationTime=, size=]
2016-09-26 16:14:21.601179 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.601179 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.601205 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=0]
2016-09-26 16:14:21.601213 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=256]
2016-09-26 16:14:21.601219 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Available() [this=7f00ac08be40, retval=262147, rv=0x00000000]
2016-09-26 16:14:21.601225 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.601231 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=7f00adfc4800 request=7f00adf0c300 status=0]
2016-09-26 16:14:21.601235 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=256]
2016-09-26 16:14:21.601244 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.601249 UTC - [Main Thread]: D/nsHttp   calling mListener->OnStartRequest
2016-09-26 16:14:21.601327 UTC - [Main Thread]: V/nsHttp HttpBaseChannel::DoApplyContentConversions [this=7f00adfc4800]
2016-09-26 16:14:21.601335 UTC - [Main Thread]: V/nsHttp not applying conversion because delivering alt-data
2016-09-26 16:14:21.601344 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.601348 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=0]
2016-09-26 16:14:21.601352 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Available() [this=7f00ac08be40, retval=262147, rv=0x00000000]
2016-09-26 16:14:21.601358 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=0]
2016-09-26 16:14:21.601363 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=7f00adfc4800 request=7f00adf0c300 offset=0 count=262147]
2016-09-26 16:14:21.601374 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=0]
2016-09-26 16:14:21.602157 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Read() [this=7f00ac08be40, count=262147]
2016-09-26 16:14:21.602166 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReadSegments() [this=7f00ac08be40, count=262147]
2016-09-26 16:14:21.602170 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.602173 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=0]
2016-09-26 16:14:21.602176 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cde90]
2016-09-26 16:14:21.602180 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262131]
2016-09-26 16:14:21.602201 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.602205 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReleaseChunk() [this=7f00ac08be40, idx=0]
2016-09-26 16:14:21.602210 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=1, caller=0, listener=7f00ac08be50]
2016-09-26 16:14:21.602214 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Found chunk 7f00ac0cdbc0 in mChunks [this=7f00aece5e00]
2016-09-26 16:14:21.602220 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0cdbc0, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.602223 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.602227 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=16]
2016-09-26 16:14:21.602232 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cde90, idx=0]
2016-09-26 16:14:21.602237 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0cde90]
2016-09-26 16:14:21.602242 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.602246 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0cde90]
2016-09-26 16:14:21.602318 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.602323 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.602327 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReadSegments() [this=7f00ac08be40, rv=0x00000000, retval=262147]
2016-09-26 16:14:21.607320 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() [this=7f00ac08b2e0, count=786442]
2016-09-26 16:14:21.607332 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.607335 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08b2e0, idx=1]
2016-09-26 16:14:21.607339 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0cdbc0, ensuredBufSize=262144]
2016-09-26 16:14:21.607343 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cdbc0, size=261632]
2016-09-26 16:14:21.607529 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 262144 [this=7f00ac0cdbc0]
2016-09-26 16:14:21.607549 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0cdbc0, offset=16, len=262128]
2016-09-26 16:14:21.607553 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.607557 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.607560 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::ReleaseChunk() [this=7f00ac08b2e0, idx=1]
2016-09-26 16:14:21.607571 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=2, caller=1, listener=0]
2016-09-26 16:14:21.607578 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0cde90, index=2, initByWriter=1]
2016-09-26 16:14:21.607583 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Created new empty chunk 7f00ac0cde90 [this=7f00aece5e00]
2016-09-26 16:14:21.607586 UTC - [Main Thread]: D/cache2 CacheFileChunk::InitNew() [this=7f00ac0cde90]
2016-09-26 16:14:21.607591 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=2, hash=d10d]
2016-09-26 16:14:21.607595 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=760]
2016-09-26 16:14:21.607598 UTC - [Main Thread]: D/cache2   mMemorySize=760 (+760,-756)
2016-09-26 16:14:21.607602 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0cde90, ensuredBufSize=262144]
2016-09-26 16:14:21.607606 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0cde90, size=262144]
2016-09-26 16:14:21.607616 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 524288 [this=7f00ac0cde90]
2016-09-26 16:14:21.607631 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0cde90, offset=0, len=262144]
2016-09-26 16:14:21.607636 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cde90]
2016-09-26 16:14:21.607639 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.607642 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::ReleaseChunk() [this=7f00ac08b2e0, idx=2]
2016-09-26 16:14:21.607647 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=3, caller=1, listener=0]
2016-09-26 16:14:21.607652 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0ce0d0, index=3, initByWriter=1]
2016-09-26 16:14:21.607656 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Created new empty chunk 7f00ac0ce0d0 [this=7f00aece5e00]
2016-09-26 16:14:21.607658 UTC - [Main Thread]: D/cache2 CacheFileChunk::InitNew() [this=7f00ac0ce0d0]
2016-09-26 16:14:21.607663 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=3, hash=d10d]
2016-09-26 16:14:21.607666 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=760]
2016-09-26 16:14:21.607669 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0ce0d0, ensuredBufSize=262144]
2016-09-26 16:14:21.607673 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0ce0d0, size=262144]
2016-09-26 16:14:21.607683 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 786432 [this=7f00ac0ce0d0]
2016-09-26 16:14:21.607699 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0ce0d0, offset=0, len=262144]
2016-09-26 16:14:21.607704 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0ce0d0]
2016-09-26 16:14:21.607707 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=0]
2016-09-26 16:14:21.607710 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::ReleaseChunk() [this=7f00ac08b2e0, idx=3]
2016-09-26 16:14:21.607714 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=4, caller=1, listener=0]
2016-09-26 16:14:21.607718 UTC - [Main Thread]: D/cache2 CacheFileChunk::CacheFileChunk() [this=7f00ac0ce1f0, index=4, initByWriter=1]
2016-09-26 16:14:21.607722 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Created new empty chunk 7f00ac0ce1f0 [this=7f00aece5e00]
2016-09-26 16:14:21.607725 UTC - [Main Thread]: D/cache2 CacheFileChunk::InitNew() [this=7f00ac0ce1f0]
2016-09-26 16:14:21.607729 UTC - [Main Thread]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=4, hash=d10d]
2016-09-26 16:14:21.607740 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.607743 UTC - [Main Thread]: D/cache2   mMemorySize=768 (+768,-760)
2016-09-26 16:14:21.607747 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetWriteHandle() [this=7f00ac0ce1f0, ensuredBufSize=26]
2016-09-26 16:14:21.607750 UTC - [Main Thread]: D/cache2 CacheFileChunk::CanAllocate() [this=7f00ac0ce1f0, size=512]
2016-09-26 16:14:21.607754 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 786944 [this=7f00ac0ce1f0]
2016-09-26 16:14:21.607757 UTC - [Main Thread]: D/cache2 CacheFileChunk::UpdateDataSize() [this=7f00ac0ce1f0, offset=0, len=26]
2016-09-26 16:14:21.607760 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0ce1f0]
2016-09-26 16:14:21.607764 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() [this=7f00ac08b2e0, releaseOnly=1]
2016-09-26 16:14:21.607767 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08b2e0, idx=4]
2016-09-26 16:14:21.607770 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Write() - Wrote 786442 bytes [this=7f00ac08b2e0]
2016-09-26 16:14:21.607776 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cde90, idx=2]
2016-09-26 16:14:21.607780 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.607783 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0cde90, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.607789 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=524288, count=262144, validate=0, truncate=0, listener=7f00ac0cde90]
2016-09-26 16:14:21.607807 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0ce0d0, idx=3]
2016-09-26 16:14:21.607811 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.607815 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0ce0d0, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.607838 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=786432, count=262144, validate=0, truncate=0, listener=7f00ac0ce0d0]
2016-09-26 16:14:21.607870 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=524288, count=262144, validate=0, truncate=0]
2016-09-26 16:14:21.608127 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::Close() [this=7f00ac08b2e0]
2016-09-26 16:14:21.608136 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::CloseWithStatus() [this=7f00ac08b2e0, aStatus=0x00000000]
2016-09-26 16:14:21.608140 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::CloseWithStatusLocked() [this=7f00ac08b2e0, aStatus=0x00000000]
2016-09-26 16:14:21.608143 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::ReleaseChunk() [this=7f00ac08b2e0, idx=4]
2016-09-26 16:14:21.608148 UTC - [Main Thread]: D/cache2 CacheFile::RemoveOutput() [this=7f00aece5e00, output=7f00ac08b2e0, status=0x80470002]
2016-09-26 16:14:21.608170 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() [this=7f00aece5e00]
2016-09-26 16:14:21.608174 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() - fail2 [this=7f00aece5e00, idx=2]
2016-09-26 16:14:21.608177 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cde90]
2016-09-26 16:14:21.608181 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() - fail2 [this=7f00aece5e00, idx=4]
2016-09-26 16:14:21.608184 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0ce1f0]
2016-09-26 16:14:21.608188 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() - fail2 [this=7f00aece5e00, idx=1]
2016-09-26 16:14:21.608194 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.608197 UTC - [Main Thread]: D/cache2 CacheFile::NotifyListenersAboutOutputRemoval() - fail2 [this=7f00aece5e00, idx=3]
2016-09-26 16:14:21.608200 UTC - [Main Thread]: D/cache2 CacheFileChunk::NotifyUpdateListeners() [this=7f00ac0ce0d0]
2016-09-26 16:14:21.608204 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.608251 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0ce1f0, idx=4]
2016-09-26 16:14:21.608257 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.608261 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0ce1f0, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.608265 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=1048576, count=26, validate=0, truncate=0, listener=7f00ac0ce1f0]
2016-09-26 16:14:21.608339 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=262147]
2016-09-26 16:14:21.608349 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=262147]
2016-09-26 16:14:21.608354 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.608358 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.608363 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Available() [this=7f00ac08be40, retval=786442, rv=0x00000000]
2016-09-26 16:14:21.608369 UTC - [Main Thread]: D/cache2 CacheFileInputStream::AsyncWait() [this=7f00ac08be40, callback=7f00adf0c308, flags=0, requestedCount=0, eventTarget=7f00b8881150]
2016-09-26 16:14:21.608372 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=768]
2016-09-26 16:14:21.608375 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.608385 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.608386 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.608392 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=256]
2016-09-26 16:14:21.608398 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=7f00adf0c308, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0cdbc0, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.608402 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.608406 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.608425 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=768]
2016-09-26 16:14:21.608448 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262128]
2016-09-26 16:14:21.608453 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.608457 UTC - [Main Thread]: D/cache2 CacheFileInputStream::NotifyListener() [this=7f00ac08be40]
2016-09-26 16:14:21.608551 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.608557 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.608560 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.608563 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 768
2016-09-26 16:14:21.608568 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=768kB, cacheSizeLimit=256000kB, freeSpace=106632794112, freeSpaceLimit=5242880]
2016-09-26 16:14:21.608592 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.608593 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0cde90, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.608602 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.608608 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Available() [this=7f00ac08be40, retval=786442, rv=0x00000000]
2016-09-26 16:14:21.608616 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=262147]
2016-09-26 16:14:21.608623 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cde90, idx=2]
2016-09-26 16:14:21.608624 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=7f00adfc4800 request=7f00adf0c300 offset=262147 count=786442]
2016-09-26 16:14:21.609506 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=2, hash=b0a2]
2016-09-26 16:14:21.609531 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.609536 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Caching unused chunk [this=7f00aece5e00, chunk=7f00ac0cde90]
2016-09-26 16:14:21.609572 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.609594 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=262147]
2016-09-26 16:14:21.609597 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=5]
2016-09-26 16:14:21.609609 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=786432, count=262144, validate=0, truncate=0]
2016-09-26 16:14:21.609803 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=1024]
2016-09-26 16:14:21.609810 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.609814 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=768]
2016-09-26 16:14:21.609836 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.609840 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=1024]
2016-09-26 16:14:21.609844 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.609906 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.609911 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.609915 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.609918 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 1024
2016-09-26 16:14:21.609922 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=1024kB, cacheSizeLimit=256000kB, freeSpace=106632531968, freeSpaceLimit=5242880]
2016-09-26 16:14:21.609940 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0ce0d0, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.609946 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0ce0d0, idx=3]
2016-09-26 16:14:21.610190 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Read() [this=7f00ac08be40, count=786442]
2016-09-26 16:14:21.610863 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=3, hash=c92c]
2016-09-26 16:14:21.610870 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.610877 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Caching unused chunk [this=7f00aece5e00, chunk=7f00ac0ce0d0]
2016-09-26 16:14:21.610900 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.610916 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.610923 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=1048576, count=26, validate=0, truncate=0]
2016-09-26 16:14:21.610959 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReadSegments() [this=7f00ac08be40, count=786442]
2016-09-26 16:14:21.610973 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.610978 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.610981 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.610988 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262128]
2016-09-26 16:14:21.611065 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.611072 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReleaseChunk() [this=7f00ac08be40, idx=1]
2016-09-26 16:14:21.611078 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=2, caller=0, listener=7f00ac08be50]
2016-09-26 16:14:21.611084 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Reusing cached chunk 7f00ac0cde90 [this=7f00aece5e00]
2016-09-26 16:14:21.611086 UTC - [Cache2 I/O]: D/cache2 CacheIndex::UpdateEntry() [hash=84de83046f61656b28c884d89367f2a73f130bdc, frecency=, expirationTime=, size=1025]
2016-09-26 16:14:21.611108 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0cde90, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.611110 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::BeforeChange()
2016-09-26 16:14:21.611132 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0cde90]
2016-09-26 16:14:21.611140 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=1024]
2016-09-26 16:14:21.611166 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262144]
2016-09-26 16:14:21.611171 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::AfterChange()
2016-09-26 16:14:21.611181 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cdbc0, idx=1]
2016-09-26 16:14:21.611183 UTC - [Cache2 I/O]: D/cache2 CacheIndexStats::Log() [count=1, notInitialized=0, removed=0, dirty=1, fresh=1, empty=0, size=1025]
2016-09-26 16:14:21.611188 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Writing dirty chunk to the disk [this=7f00aece5e00]
2016-09-26 16:14:21.611192 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal()
2016-09-26 16:14:21.611201 UTC - [Main Thread]: D/cache2 CacheFileChunk::Write() [this=7f00ac0cdbc0, handle=7f00ac091680, listener=7f00aece5e00]
2016-09-26 16:14:21.611208 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=262144, count=262144, validate=0, truncate=0, listener=7f00ac0cdbc0]
2016-09-26 16:14:21.611254 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate()
2016-09-26 16:14:21.611260 UTC - [Cache2 I/O]: D/cache2 CacheIndex::IsUpToDate() - returning 0
2016-09-26 16:14:21.611264 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize()
2016-09-26 16:14:21.611267 UTC - [Cache2 I/O]: D/cache2 CacheIndex::GetCacheSize() - returning 1025
2016-09-26 16:14:21.611270 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.611273 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::EvictIfOverLimitInternal() - Cache size and free space in limits. [cacheSize=1025kB, cacheSizeLimit=256000kB, freeSpace=106632527872, freeSpaceLimit=5242880]
2016-09-26 16:14:21.611286 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0ce1f0, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.611276 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReleaseChunk() [this=7f00ac08be40, idx=2]
2016-09-26 16:14:21.611297 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=3, caller=0, listener=7f00ac08be50]
2016-09-26 16:14:21.611301 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Reusing cached chunk 7f00ac0ce0d0 [this=7f00aece5e00]
2016-09-26 16:14:21.611324 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0ce0d0, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.611327 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0ce0d0]
2016-09-26 16:14:21.611331 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=262144]
2016-09-26 16:14:21.611341 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0ce1f0, idx=4]
2016-09-26 16:14:21.611347 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=4, hash=8c9c]
2016-09-26 16:14:21.611351 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.611355 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Caching unused chunk [this=7f00aece5e00, chunk=7f00ac0ce1f0]
2016-09-26 16:14:21.611382 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.611390 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.611392 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.611397 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=262144, count=262144, validate=0, truncate=0]
2016-09-26 16:14:21.611397 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReleaseChunk() [this=7f00ac08be40, idx=3]
2016-09-26 16:14:21.611408 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() [this=7f00aece5e00, idx=4, caller=0, listener=7f00ac08be50]
2016-09-26 16:14:21.611412 UTC - [Main Thread]: D/cache2 CacheFile::GetChunkLocked() - Reusing cached chunk 7f00ac0ce1f0 [this=7f00aece5e00]
2016-09-26 16:14:21.611418 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=0, mStatus=0x00000000, mChunk=7f00ac0ce1f0, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.611421 UTC - [Main Thread]: D/cache2 CacheFileChunk::GetReadHandle() [this=7f00ac0ce1f0]
2016-09-26 16:14:21.611425 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CanRead() [this=7f00ac08be40, canRead=26]
2016-09-26 16:14:21.611430 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.611433 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=4]
2016-09-26 16:14:21.611437 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReadSegments() [this=7f00ac08be40, rv=0x00000000, retval=786442]
2016-09-26 16:14:21.611550 UTC - [Cache2 I/O]: D/cache2 CacheFileChunk::OnDataWritten() [this=7f00ac0cdbc0, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.611557 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() [this=7f00aece5e00, rv=0x00000000, chunk=7f00ac0cdbc0, idx=1]
2016-09-26 16:14:21.612444 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::SetHash() [this=7f00b6a85f20, idx=1, hash=465b]
2016-09-26 16:14:21.612456 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.612469 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnChunkWritten() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0cdbc0]
2016-09-26 16:14:21.612503 UTC - [Cache2 I/O]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.612518 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.613010 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=1048589]
2016-09-26 16:14:21.613045 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Tell() [this=7f00ac08be40, retval=1048589]
2016-09-26 16:14:21.613072 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() [this=7f00ac08be40, releaseOnly=0]
2016-09-26 16:14:21.613077 UTC - [Main Thread]: D/cache2 CacheFileInputStream::EnsureCorrectChunk() - Have correct chunk [this=7f00ac08be40, idx=4]
2016-09-26 16:14:21.613083 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Available() [this=7f00ac08be40, retval=0, rv=0x80470002]
2016-09-26 16:14:21.613091 UTC - [Main Thread]: D/cache2 CacheFileInputStream::Close() [this=7f00ac08be40]
2016-09-26 16:14:21.613097 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CloseWithStatus() [this=7f00ac08be40, aStatus=0x00000000]
2016-09-26 16:14:21.613103 UTC - [Main Thread]: D/cache2 CacheFileInputStream::CloseWithStatusLocked() [this=7f00ac08be40, aStatus=0x00000000]
2016-09-26 16:14:21.613108 UTC - [Main Thread]: D/cache2 CacheFileInputStream::ReleaseChunk() [this=7f00ac08be40, idx=4]
2016-09-26 16:14:21.613126 UTC - [Main Thread]: D/cache2 CacheFileInputStream::MaybeNotifyListener() [this=7f00ac08be40, mCallback=0, mClosed=1, mStatus=0x80470002, mChunk=0, mListeningForChunk=-1, mWaitingForUpdate=0]
2016-09-26 16:14:21.613139 UTC - [Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=7f00ac093c00, state=READY, handle=7f00ac0c7800]
2016-09-26 16:14:21.613149 UTC - [Main Thread]: D/cache2   not the writer
2016-09-26 16:14:21.613160 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=7f00adfc4800 request=7f00adf0c300 status=0]
2016-09-26 16:14:21.613164 UTC - [Main Thread]: D/nsHttp   dropping upload stream
2016-09-26 16:14:21.613170 UTC - [Main Thread]: D/nsHttp   calling OnStopRequest
2016-09-26 16:14:21.722133 UTC - [Main Thread]: D/nsHttp nsHttpChannel::CloseCacheEntry [this=7f00adfc4800] mStatus=0 mCacheEntryIsWriteOnly=0
2016-09-26 16:14:21.722393 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0cde90, idx=2]
2016-09-26 16:14:21.722415 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0cde90]
2016-09-26 16:14:21.722426 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.722437 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0cde90]
2016-09-26 16:14:21.722469 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 524800 [this=7f00ac0cde90]
2016-09-26 16:14:21.722624 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0ce0d0, idx=3]
2016-09-26 16:14:21.722641 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Releasing unused chunk [this=7f00aece5e00, chunk=7f00ac0ce0d0]
2016-09-26 16:14:21.722652 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.722661 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0ce0d0]
2016-09-26 16:14:21.722689 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 262656 [this=7f00ac0ce0d0]
2016-09-26 16:14:21.722842 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() [this=7f00aece5e00, chunk=7f00ac0ce1f0, idx=4]
2016-09-26 16:14:21.722860 UTC - [Main Thread]: D/cache2 CacheFile::DeactivateChunk() - Caching unused chunk [this=7f00aece5e00, chunk=7f00ac0ce1f0]
2016-09-26 16:14:21.722871 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.723034 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0cdbc0]
2016-09-26 16:14:21.723069 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 512 [this=7f00ac0cdbc0]
2016-09-26 16:14:21.724089 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 7f00aecd0200 caps=0x401 ......localhost:34047
2016-09-26 16:14:21.724122 UTC - [Socket Thread]: V/nsHttp Server initiated close of idle conn 7f00aecd0200
2016-09-26 16:14:21.724136 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::CloseIdleConnection 7f00b887e1e0 conn=7f00aecd0200
2016-09-26 16:14:21.724156 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Close [this=7f00aecd0200 reason=80004004]
2016-09-26 16:14:21.724169 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::EndIdleMonitoring [this=7f00aecd0200]
2016-09-26 16:14:21.724179 UTC - [Socket Thread]: V/nsHttp Leaving Idle Monitoring Mode [this=7f00aecd0200]
2016-09-26 16:14:21.724199 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Close drained 0 bytes
2016-09-26 16:14:21.724227 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::StopPruneDeadConnectionsTimer
2016-09-26 16:14:21.724255 UTC - [Socket Thread]: V/nsHttp Destroying nsHttpConnection @7f00aecd0200
2016-09-26 16:14:21.724266 UTC - [Socket Thread]: V/nsHttp nsHttpConnection 7f00aecd0200 performed 0 HTTP/1.x transactions
2016-09-26 16:14:21.815366 UTC - [Main Thread]: D/nsHttp Destroying nsHttpChannel [this=7f00adfc4800]
2016-09-26 16:14:21.815411 UTC - [Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=7f00ac093c00, state=READY, handle=7f00ac0c7f80]
2016-09-26 16:14:21.815419 UTC - [Main Thread]: D/cache2   not the writer
2016-09-26 16:14:21.815429 UTC - [Main Thread]: V/nsHttp Destroying HttpBaseChannel @adfc4800
2016-09-26 16:14:21.815450 UTC - [Main Thread]: D/nsHttp Destroying nsHttpConnectionInfo @b8879040
2016-09-26 16:14:21.815480 UTC - [Main Thread]: D/cache2 CacheFile::RemoveInput() [this=7f00aece5e00, input=7f00ac08be40, status=0x80470002]
2016-09-26 16:14:21.815495 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.815524 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() - Writing metadata [this=7f00aece5e00]
2016-09-26 16:14:21.815534 UTC - [Main Thread]: D/cache2 CacheFileMetadata::WriteMetadata() [this=7f00b6a85f20, offset=1048602, listener=7f00aece5e10]
2016-09-26 16:14:21.815559 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Write() [handle=7f00ac091680, offset=1048602, count=504, validate=1, truncate=1, listener=7f00b6a85f20]
2016-09-26 16:14:21.815590 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.815597 UTC - [Main Thread]: D/cache2 CacheFile::CleanUpCachedChunks() [this=7f00aece5e00, idx=4, chunk=7f00ac0ce1f0]
2016-09-26 16:14:21.815602 UTC - [Main Thread]: D/cache2 CacheFile::CleanUpCachedChunks() - Removing chunk
2016-09-26 16:14:21.815608 UTC - [Main Thread]: D/cache2 CacheFileChunk::~CacheFileChunk() [this=7f00ac0ce1f0]
2016-09-26 16:14:21.815617 UTC - [Main Thread]: D/cache2 CacheFileChunk::BuffersAllocationChanged() - Normal chunks usage 0 [this=7f00ac0ce1f0]
2016-09-26 16:14:21.815626 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::WriteInternal() [handle=7f00ac091680, offset=1048602, count=504, validate=1, truncate=1]
2016-09-26 16:14:21.815665 UTC - [Main Thread]: D/cache2 CacheFileInputStream::~CacheFileInputStream() [this=7f00ac08be40]
2016-09-26 16:14:21.815677 UTC - [Main Thread]: D/nsHttp Destroying nsHttpChannel [this=7f00adf56000]
2016-09-26 16:14:21.815685 UTC - [Main Thread]: D/cache2 CacheEntry::OnHandleClosed [this=7f00ac093c00, state=READY, handle=7f00b8816660]
2016-09-26 16:14:21.815703 UTC - [Main Thread]: D/cache2 CacheEntry::BackgroundOp this=7f00ac093c00 dipatch of 4
2016-09-26 16:14:21.815712 UTC - [Main Thread]: V/nsHttp Destroying HttpBaseChannel @adf56000
2016-09-26 16:14:21.815726 UTC - [Main Thread]: D/nsHttp Destroying nsHttpConnectionInfo @b8878da0
2016-09-26 16:14:21.815820 UTC - [Cache2 I/O]: D/cache2 CacheFileMetadata::OnDataWritten() [this=7f00b6a85f20, handle=7f00ac091680, result=0x00000000]
2016-09-26 16:14:21.815831 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() [this=7f00aece5e00, rv=0x00000000]
2016-09-26 16:14:21.815837 UTC - [Cache2 I/O]: D/cache2 CacheFile::OnMetadataWritten() - Releasing file handle [this=7f00aece5e00]
2016-09-26 16:14:21.815842 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::ReleaseNSPRHandle() [handle=7f00ac091680]
2016-09-26 16:14:21.815859 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=768]
2016-09-26 16:14:21.815868 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=4]
2016-09-26 16:14:21.815882 UTC - [Cache2 I/O]: D/cache2 CacheEntry CALLBACKS (invoke) [this=7f00ac093c00]
2016-09-26 16:14:21.815888 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeCallbacks BEGIN [this=7f00ac093c00]
2016-09-26 16:14:21.815894 UTC - [Cache2 I/O]: D/cache2 CacheEntry::InvokeCallbacks END [this=7f00ac093c00]
2016-09-26 16:14:21.815903 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::MaybeReleaseNSPRHandleInternal() [handle=7f00ac091680, ignore shutdown=0]
2016-09-26 16:14:21.815911 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::MaybeReleaseNSPRHandleInternal() DONE
2016-09-26 16:14:21.815918 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.831043 UTC - [Main Thread]: D/nsHttp nsHttpHandler::Observe [topic="profile-change-net-teardown"]
2016-09-26 16:14:21.831096 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::ClearAll
2016-09-26 16:14:21.831115 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::ClearAll
2016-09-26 16:14:21.831124 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::Shutdown
2016-09-26 16:14:21.831294 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgShutdown
2016-09-26 16:14:21.831326 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::StopPruneDeadConnectionsTimer
2016-09-26 16:14:21.831340 UTC - [Socket Thread]: D/nsHttp Destroying nsHttpConnectionInfo @b8878cc0
2016-09-26 16:14:21.831397 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgShutdownConfirm
2016-09-26 16:14:21.858499 UTC - [Main Thread]: D/cache2 CacheStorageService::Shutdown - start
2016-09-26 16:14:21.858530 UTC - [Main Thread]: D/cache2 CacheStorageService::Shutdown - done
2016-09-26 16:14:21.858537 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=7f00adf915c0]
2016-09-26 16:14:21.858543 UTC - [Main Thread]: D/cache2 CacheIndex::PreShutdown() [gInstance=7f00aecd1240]
2016-09-26 16:14:21.858549 UTC - [Main Thread]: D/cache2 CacheIndex::PreShutdown() - [state=3, indexOnDiskIsValid=0, dontMarkIndexClean=0]
2016-09-26 16:14:21.858553 UTC - [Main Thread]: D/cache2 CacheIndex::PreShutdown() - Closing iterators.
2016-09-26 16:14:21.858629 UTC - [Cache2 I/O]: D/cache2 CacheIndex::PreShutdownInternal() - [state=3, indexOnDiskIsValid=0, dontMarkIndexClean=0]
2016-09-26 16:14:21.858663 UTC - [Cache2 I/O]: D/cache2 CacheIndex::FinishUpdate() [succeeded=0]
2016-09-26 16:14:21.858668 UTC - [Cache2 I/O]: D/cache2 CacheIndex::ChangeState() changing state BUILDING -> READY
2016-09-26 16:14:21.858671 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::CacheIndexStateChanged()
2016-09-26 16:14:21.858730 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::ShutdownBackground - start
2016-09-26 16:14:21.858754 UTC - [Cache2 I/O]: D/cache2 CacheEntry::~CacheEntry [this=7f00ac093c00]
2016-09-26 16:14:21.858763 UTC - [Cache2 I/O]: D/cache2 CacheStorageService::ShutdownBackground - done
2016-09-26 16:14:21.858787 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::ShutdownInternal() [this=7f00adf915c0]
2016-09-26 16:14:21.858800 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Log() - entry file [this=7f00ac091680, hash=84de83046f61656b28c884d89367f2a73f130bdc, isDoomed=0, priority=0, closed=1, invalid=0, pinning=1, fileExists=1, fileSize=1049106, leafName=84DE83046F61656B28C884D89367F2A73F130BDC, key=:http://localhost:34047/content]
2016-09-26 16:14:21.858811 UTC - [Cache2 I/O]: D/cache2 CacheFileIOManager::MaybeReleaseNSPRHandleInternal() [handle=7f00ac091680, ignore shutdown=0]
2016-09-26 16:14:21.858817 UTC - [Cache2 I/O]: D/cache2 CacheFileHandles::RemoveHandle() hash=84de83046f61656b28c884d89367f2a73f130bdc removing handle 7f00ac091680
2016-09-26 16:14:21.858822 UTC - [Cache2 I/O]: D/cache2 CacheFileHandles::RemoveHandle() hash=84de83046f61656b28c884d89367f2a73f130bdc list is empty, removing entry 7f00adf71c50
2016-09-26 16:14:21.858827 UTC - [Cache2 I/O]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=3]
2016-09-26 16:14:21.858859 UTC - [Main Thread]: D/cache2 CacheIndex::Shutdown() [gInstance=7f00aecd1240]
2016-09-26 16:14:21.858884 UTC - [Main Thread]: D/cache2 CacheIndex::Shutdown() - [state=5, indexOnDiskIsValid=0, dontMarkIndexClean=1, sanitize=0]
2016-09-26 16:14:21.858888 UTC - [Main Thread]: D/cache2 CacheIndex::ChangeState() changing state READY -> SHUTDOWN
2016-09-26 16:14:21.858910 UTC - [Main Thread]: D/cache2 CacheIndex::RemoveJournalAndTempFile()
2016-09-26 16:14:21.858929 UTC - [Main Thread]: D/cache2 CacheIndex::~CacheIndex [this=7f00aecd1240]
2016-09-26 16:14:21.858938 UTC - [Main Thread]: D/cache2 CacheIndexEntry::~CacheIndexEntry() - Deleting record [rec=7f00ac0ab280]
2016-09-26 16:14:21.858946 UTC - [Main Thread]: D/cache2 CacheFileIOManager::~CacheFileIOManager [this=7f00adf915c0]
2016-09-26 16:14:21.858956 UTC - [Main Thread]: D/cache2 CacheFileHandles::~CacheFileHandles() [this=7f00adf91600]
2016-09-26 16:14:21.944890 UTC - [Main Thread]: D/cache2 CacheFile::RemoveOutput() [this=7f00aece5e00, output=7f00ac08b2e0, status=0x80470002]
2016-09-26 16:14:21.944923 UTC - [Main Thread]: D/cache2 CacheFile::RemoveOutput() - This output was already removed, ignoring call [this=7f00aece5e00]
2016-09-26 16:14:21.944934 UTC - [Main Thread]: D/cache2 CacheFileOutputStream::~CacheFileOutputStream() [this=7f00ac08b2e0]
2016-09-26 16:14:21.944941 UTC - [Main Thread]: D/cache2 CacheFile::~CacheFile() [this=7f00aece5e00]
2016-09-26 16:14:21.944948 UTC - [Main Thread]: D/cache2 CacheFile::WriteMetadataIfNeededLocked() [this=7f00aece5e00]
2016-09-26 16:14:21.944958 UTC - [Main Thread]: D/cache2 CacheFileMetadata::~CacheFileMetadata() [this=7f00b6a85f20]
2016-09-26 16:14:21.944968 UTC - [Main Thread]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=2]
2016-09-26 16:14:21.944976 UTC - [Main Thread]: D/cache2 CacheStorageService::OnMemoryConsumptionChange [consumer=7f00b6a85f28, size=0]
2016-09-26 16:14:21.944985 UTC - [Main Thread]: D/cache2   mMemorySize=0 (+0,-768)
2016-09-26 16:14:21.944994 UTC - [Main Thread]: D/cache2 CacheFileHandle::Release() [this=7f00ac091680, refcnt=1]
2016-09-26 16:14:21.945001 UTC - [Main Thread]: D/cache2 CacheFileHandle::~CacheFileHandle() [this=7f00ac091680]
2016-09-26 16:14:22.018553 UTC - [Main Thread]: D/nsHttp nsHttpHandler::Observe [topic="xpcom-shutdown"]
2016-09-26 16:14:22.018599 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::ClearAll
2016-09-26 16:14:22.018612 UTC - [Main Thread]: D/nsHttp nsHttpAuthCache::ClearAll
2016-09-26 16:14:22.018625 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::Shutdown
2016-09-26 16:14:22.018733 UTC - [Main Thread]: D/cache2 CacheFileIOManager::Shutdown() [gInstance=0]
2016-09-26 16:14:22.023428 UTC - [Main Thread]: D/cache2 CacheStorageService::~CacheStorageService
2016-09-26 16:14:22.023576 UTC - [Main Thread]: D/nsHttp Deleting nsHttpHandler [this=7f00adf84000]
2016-09-26 16:14:22.023592 UTC - [Main Thread]: V/nsHttp nsHttpConnectionMgr::Shutdown
2016-09-26 16:14:22.023607 UTC - [Main Thread]: V/nsHttp Destroying nsHttpConnectionMgr @7f00b887e1e0