Very weird problem here . Been banging my head for 2 days

[Petko Ditchev]

Not two whole days , but still . Here's the problem - I'm building an extension to sync tabs in real time (like Tab Auto sync but simpler and hopefully less buggy) . onInstall and onStartup I call startUp() . Here's the super weird part - I get the current and stored in 'syncTabs' tabs via the  chrome.tabs.query and chrome.storage.sync.get in startUp() , but in mergeTabsFromSync() I get empty arrays from the same methods . In theory the code executed is the same , but I just get a result in startUp , and empty arrays in mergeTabsFromSync(). And I just can't understand what changes in the environment . More info : that only happens on the actual startup . If I call mergeTabsFromSync() in the console I get correct readings . It's probably something very stupid but I just cant see it .

Here's the output:

'onInstalled' event fired . Reason: update background.js:69

startUp() called: evaluating 'power' var from local storage background.js:99

'syncTabs' pulled from storage:

Array[2]

background.js:104

Current tabs:

Array[2]

background.js:109

'power' is true. background.js:114

In function mergeTabsFromSync() background.js:158

'syncTabs' pulled from storage:

Object

background.js:163

updateTabsFromStringList() started

Array[0]

background.js:288

Current tabs:

Array[0]

background.js:292

updateTabsFromStringList() ended background.js:350

updateStorageFromTabs_directly() started. background.js:393

'syncTabs' pulled from storage:

Array[0]

background.js:405

Current tabs:

Array[2]

background.js:421

updateStorageFromTabs_directly() ended. background.js:471

mergeTabsFromSync() ended. background.js:179

And here's the code :

//

// On startup - take into account the power variable (whether the sync is enabled by the user)

///////////////////////////////////////////

function startUp( callback ) {

console.log("startUp() called: evaluating 'power' var from local storage");

chrome.storage.sync.get( 'syncTabs', function( returnVal ) { //just for testing

syncTabs = returnVal.syncTabs; //returnval is a key:value pair, we need only the value

console.log("'syncTabs' pulled from storage: ",syncTabs);

        // Get current tabs

        chrome.tabs.query( {} , function (tabs) { //query with no specifier so we get all tabs

console.log("Current tabs: ",tabs);

chrome.storage.local.get( "power", function( data ) {

if( data.power === true ){

console.log("'power' is true.");

if(!syncingIsStarted){

mergeTabsFromSync(function(){

indicateExtensionIsOn();

startSyncing();

console.log("startUp() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

}

}else if( data.power === false ) {

console.log("'power' is false.");

indicateExtensionIsOff();

if(syncingIsStarted){

stopSyncing();

}

}else{

console.log("'power' is non existent or an invalid value.");

activateSyncing(function(){

if(!syncingIsStarted){

mergeTabsFromSync(function(){

indicateExtensionIsOn();

startSyncing();

console.log("startUp() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

}

});

}

});

        });

});

}

function mergeTabsFromSync( callback ){

console.log("In function mergeTabsFromSync()");

//setTimeout(function(){

chrome.storage.sync.get( 'syncTabs', function( returnVal2 ) { //get synced tabs

console.log("'syncTabs' pulled from storage: ",returnVal2);

if(!returnVal2.syncTabs){

console.log("No 'syncTabs' in storage. Calling updateStorageFromTabs_directly().")

updateStorageFromTabs_directly(function(){

console.log("mergeTabsFromSync() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

}

syncTabs = returnVal2.syncTabs;

updateTabsFromStringList( syncTabs ,true ,function(){ //merge (and not replace that's what the 'true' is for) from the syncTabs list

updateStorageFromTabs_directly(function(){ //call an update

console.log("mergeTabsFromSync() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

});

});

//},6000);

}

[Róbert Csala]

My extension has similar issues sometimes, it seems that the sync store will return empty values until it is actually synced. 

Maybe it's worth hooking into the onChanged event and see whether it is fired..

I hope this helps

Rob

[Petko Ditchev]

The weird thing is that even chrome.tabs.query returns an empty array , and it's not sync-dependent . + both queries returned corectly 2 lines of javascript earlier in the startUp() .

[Petko Ditchev]

Here's the actual extension : https://chrome.google.com/webstore/detail/bflolmfdngaflefhmapdbbjmclioljck/ . It's link-only , because its pretty much an alfa , and I havent got a preview video. I believe when you get it all of the source is available.

[Adrian Aichner]

Should at least be checking for lastError

                chrome.storage.sync.get(null, function(items) {
                    try {
                        if (chrome.runtime.lastError) {
                            console.warn(chrome.runtime.lastError.message);
                        } else {

--
You received this message because you are subscribed to the Google Groups "Chromium-extensions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chromium-extens...@chromium.org.
To post to this group, send email to chromium-...@chromium.org.
Visit this group at http://groups.google.com/a/chromium.org/group/chromium-extensions/.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-extensions/bf139210-4ec1-4dfb-a528-f3a57cca6334%40chromium.org.
For more options, visit https://groups.google.com/a/chromium.org/groups/opt_out.

[Petko Ditchev]

I checked for it in the console , but I gues that could have been out of scope . I'll try it out now , but if lastError doesn't get cleared out when the scope changes consider it checked

[Petko Ditchev]

No error is thrown . I did a console.log(chrome.extension.lastError) in the callback of chrome.storage.sync.get() . By API the lastError should be defined in this scope .

[Róbert Csala]

It's chrome.runtime.lastError

On 7 Nov 2013 18:18, "Petko Ditchev" <pdit...@gmail.com> wrote:

No error is thrown . I did a console.log(chrome.extension.lastError) in the callback of chrome.storage.sync.get() . By API the lastError should be defined in this scope .

--

You received this message because you are subscribed to the Google Groups "Chromium-extensions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chromium-extens...@chromium.org.
To post to this group, send email to chromium-...@chromium.org.
Visit this group at http://groups.google.com/a/chromium.org/group/chromium-extensions/.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-extensions/ad4b3d25-a366-49e0-b3e4-d7e5f95d9644%40chromium.org.

[Petko Ditchev]

Same , undefined . Still no clue ...

[Terry Jones]

Hi Petko

If it's any consolation, I've also had times where I was getting an empty array from chrome.tabs.query. I don't remember the details but it was definitely on extension startup, I definitely was passing no qualifiers to restrict what tabs should be returned, and I couldn't make it reproducible. I know that's not very helpful, but it may confirm that you're not hallucinating :-)

Terry

--

You received this message because you are subscribed to the Google Groups "Chromium-extensions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chromium-extens...@chromium.org.
To post to this group, send email to chromium-...@chromium.org.
Visit this group at http://groups.google.com/a/chromium.org/group/chromium-extensions/.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-extensions/bf139210-4ec1-4dfb-a528-f3a57cca6334%40chromium.org.

[Petko Ditchev]

The thing is that it is reproducible - I get the same thing on every startup - the query in startUp() returns correctly , and 3 lines later the query returns empty (given at first I didn't do the test query in startUp() . As you may have noticed it is redundant .
    The problem is something very stupid breakage that I just cannot see (which happened when I abstracted mergeTabsFromSync from the startUp function). So I'll go get the old source from dropbox and try it line by line . I just hoped it wouldn't come to that :D

[Petko Ditchev]

Ok , I didn't have time to post about it , but I gave it a few hours and the main conclusion is that JavaScript doesn't deserve being called a script language . Apparently code that appears afterwards can cause breakage now . Here's where I'm at : we have the function below . On the start of the extension onStartup (or onInstalled) calles startUp() , which calls mergeTabsFromSync() (everything till this point is perfect) , which calls update tabs from string list (after getting the string list of URLs from the sync storage) . Now - simply put - we call the function below for the first time and the very first console.log() shows that syncTabs is an array with zero elements. We go through hours of trial and error ,and we see that if the line "syncTabs.splice(s,1);" is commented out - the first console log actually returns the array passed as a parameter ('syncTabs') correctly . Now $@%$ what ?

//Does not remove/readd events for itself

function updateTabsFromStringList(syncTabs,do_merge,callback) {

//var syncTabs=syncTabs1.slice(); //-ne staaa

console.log(Date.now()-time_of_start,'updateTabsFromStringList() started',syncTabs);

//Synchronize tabs

chrome.tabs.query( {} , function (currentTabs) { //query with no specifier so we get all tabs

console.log(Date.now()-time_of_start,":","Current tabs: ",currentTabs);

if(!currentTabs){

console.log(Date.now()-time_of_start,":","No tabs returned by the query. Returning updateTabsFromStringList().");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

}

//For all local tabs

for( var t = 0; t < currentTabs.length; t++ ) {

if( currentTabs[t].url === "chrome://newtab/") { //ignore newtabs

currentTabs.splice(t,1);

t--;

continue;

}

var str = currentTabs[t].url;

if( str.slice(0,18) === "chrome-devtools://" ){ //if the tab is some kind of dev tool - leave it alone

currentTabs.splice(t,1);

t--;

continue;

}

// For all sync tabs (those in the sync DB)

for( var s = 0; s < syncTabs.length; s++ ) {

if( syncTabs[s] === currentTabs[t].url ) {//if we find the tab in sync - remove it from the sync and tabs lists

//syncTabs.splice(s,1);// !!!!!!!!!!!!!!!!!!!!!!!!!!1

currentTabs.splice(t,1);

t--; //object is removed => the one in its place is not inspected =>loop with the same index

break;

}

}//next sync tab

}//next local tab

if( ( (syncTabs.length===1) && (currentTabs.length===1) ) && (!do_merge) ) { //if there's one removed and one added - we assume it's an update

chrome.tabs.update(currentTabs[0].id, { url: syncTabs[0] , active : false } );

}else{

//Add tabs left in syncTabs (therefore not present)

for( var l = 0; l < syncTabs.length; l++ ) {

console.log("Create tab",syncTabs[l]);

//chrome.tabs.create( { url: syncTabs[l], active : false } );!!!!!!!!!!!!!!!!!!!!!!

}

if(!do_merge){

//Remove tabs left in the local tabs array (not present in sync)

for( var lt = 0; lt < currentTabs.length; lt++ ) {

console.log(Date.now()-time_of_start,":","Removing tab",currentTabs[lt]);

//chrome.tabs.remove( tabs[lt].id); !!!!!!!!!!!!!!!!!!!!!!

}

}

}

console.log(Date.now()-time_of_start,":",'updateTabsFromStringList() ended');

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

}//end updateTabsFromStringList()

[Raymond Hill]

I am pretty sure `console.log` is asynchronous, and so is `chrome.tabs.query()`, so it appears from your result that `chrome.tabs.query()` got executed first, and `console.log()` after.

[Petko Ditchev]

Per this http://stackoverflow.com/questions/5127532/is-node-js-console-log-asynchronous console.log() is synchronous , but nevertheless we're still not talking about the tabs.query returning an empty array , but for the very first console.log in the function for syncTabs . Baring in mind this happens at the first execution only, I've looked over the variables a 100 times for some global declaration or something , that may cause this one time behavior , but - nothing . I assumed the same problem with currentTabs , removed the block for( var s = 0; s < syncTabs.length; s++ ){} (removing just the currentTabs.splice(...) broke the extension in a strange way without an error , but that's a whole different story) . So that's what we have confirmed - the .splice calls in the future corrupt the variable in the whole function in the first call.

I've attached the .crx as of writing this post.

[Raymond Hill]

Well, Chromium is not Node.js, my understanding is that `console.log` is asynchronous in the browser.

Now, I tried your extension. I might not understand properly all the code, but aren't you missing a `return` at line 159 of `background.js`? I did add this, and un-commented the code you say causes corruption, and all went through fine.

[Petko Ditchev]

 I'm very sorry that I kind of spammed the group with that , but I believe it's a pretty interesting case and/or a bug in Chromium that needs to be fixed . I have practically no JavaScript experience prior to this extension (much C++ though) , and I have no idea how the extensions are loaded in Chromium in specifics , but I deducted that there are some code optimizations made on load time ,since as mentioned earlier removing some lines broke the prior execution . The point at which I realized that's what's causing my bug is when I turned the extension "soft-off" ( startUp() checks for a 'power' var in local.storage and doesn't start syncing if 'power' is false) , and that left only the control listeners on , meaning those :

chrome.tabs.onCreated.addListener( function(){

console.log(Date.now()-time_of_start,":","Tab event detected: created");});

chrome.tabs.onUpdated.addListener( function(tabid,chng_info,tab){

console.log(Date.now()-time_of_start,":","Tab event detected: updated. ",chng_info,tab);});

chrome.tabs.onRemoved.addListener( function(){

console.log(Date.now()-time_of_start,":","Tab event detected: removed");});

chrome.storage.onChanged.addListener( function (changes,storages) {

console.log(Date.now()-time_of_start,":","Storage change event detected",changes,storages);

});

And the console gave the following on Chrome startup: 

464 ":" "'onStartup' event fired . Calling startUp() " background.js:67

465 ":" "startUp() called: evaluating 'power' var from local storage" background.js:101

518 ":" "Tab event detected: updated. "

Object

Object

background.js:28

898 ":" "Tab event detected: updated. "

Object

Object

background.js:28

950 ":" "Tab event detected: updated. "

Object

Object

background.js:28

1066 ":" "Tab event detected: updated. "

Object

Object

background.js:28

1072 ":" "Tab event detected: updated. "

Object

Object

background.js:28

'power' is false. background.js:119

Indicating extension is off. background.js:461

1546 ":" "Tab event detected: updated. "

Object

Object

background.js:28

1777 ":" "Tab event detected: updated. "

Object

Object

background.js:28

2348 ":" "Tab event detected: updated. "

Object

Object

background.js:28

2373 ":" "Tab event detected: updated. "

Object

Object

background.js:28

3529 ":" "Tab event detected: updated. "

Object

Object

background.js:28

5811 ":" "Tab event detected: updated. "

Object

Object

background.js:28

5990 ":" "Tab event detected: updated. "

Object

Object

background.js:28

6121 ":" "Tab event detected: created" background.js:26

6421 ":" "Tab event detected: updated. "

Object

Object

background.js:28

6813 ":" "Tab event detected: updated. "

Object

Object

background.js:28

7013 ":" "Tab event detected: updated. " Object {status: "loading"}

Object {active: false, highlighted: false, id: 11, incognito: false, index: 0…}

background.js:28

7037 ":" "Tab event detected: updated. " Object {status: "complete"}

Object {active: false, favIconUrl: "https://fbstatic-a.akamaihd.net/rsrc.php/yl/r/H3nktOa7ZMg.ico", highlighted: false, id: 11, incognito: false…}

background.js:28

7751 ":" "Tab event detected: updated. " Object {status: "loading"}

Object {active: false, favIconUrl: "https://fbstatic-a.akamaihd.net/rsrc.php/yl/r/H3nktOa7ZMg.ico", highlighted: false, id: 15, incognito: false…}

background.js:28

7845 ":" "Tab event detected: updated. " Object {status: "complete"}

Object {active: false, favIconUrl: "https://fbstatic-a.akamaihd.net/rsrc.php/yl/r/H3nktOa7ZMg.ico", highlighted: false, id: 15, incognito: false…}

The objects in the beginning are collapsible (their contents are correct) , but clearly at some point even the console starts behaving differently , and after that moment my functions start working correctly too , but prior to that the bugs are present and bizarre.

If anyone has an idea what's happening on extension load time in Chrome - that would clarify what's happening .

[Petko Ditchev]

 I didn't see you posting while I wrote the last comment . Thanks for taking a look . For me line 159 is at an irrelevant place in the code (execution just doesn't go there because returnVal is always defined (at least in my tests) ):

 

function mergeTabsFromSync( callback ){

console.log(Date.now()-time_of_start,":","In function mergeTabsFromSync()");

//setTimeout(function(){

chrome.storage.sync.get( 'syncTabs', function( returnVal ) { //get synced tabs

console.log(Date.now()-time_of_start,":","'syncTabs' pulled from storage: ",returnVal.syncTabs);

if(!returnVal.syncTabs){

console.log(Date.now()-time_of_start,":","No 'syncTabs' in storage. Calling updateStorageFromTabs_directly().")

updateStorageFromTabs_directly(function(){

console.log(Date.now()-time_of_start,":","mergeTabsFromSync() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

//<------- HERE is 159

}

//var syncTabs=returnVal.syncTabs.slice();

updateTabsFromStringList( returnVal.syncTabs.slice() ,true ,function(){ //merge (and not replace that's what the 'true' is for) from the syncTabs list

updateStorageFromTabs_directly(function(){ //call an update

console.log(Date.now()-time_of_start,":","mergeTabsFromSync() ended.");

if( callback && typeof( callback ) === "function" ) { callback(); }

return;

});

});

});

//},6000);

}

[Scott Fujan]

Chrome started aggressively deleting objects that are referenced only by the console recently. At least when it is closed. I think that this was an attempt to address a perceived memory leak if too many objects were logged to the console. It does many debugging inconvenient for many use cases. My suggestion is to JSON.stringify the object if you can.

--

You received this message because you are subscribed to the Google Groups "Chromium-extensions" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chromium-extens...@chromium.org.
To post to this group, send email to chromium-...@chromium.org.
Visit this group at http://groups.google.com/a/chromium.org/group/chromium-extensions/.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chromium-extensions/77c468cb-24a2-412c-b477-cc9f09981b19%40chromium.org.

[Petko Ditchev]

Ah , I understand , console output changes it's formatting not on some
load-time event , but when I open the dev-tools . That's no problem ,
because as I wrote under the output - the 'Object'-s have an arrow on
the left and are collapsible ( I can see their contents ,even though
they are not copied in the email) . So back to the drawing board , the
change in console formatting isn't a clue after all.

[Petko Ditchev]

Ok , it did turn out to be a console.log problem - the 'Objects' that
showed [0] items were actually correct at runtime , and when I wrote :
console.log("SyncTabs",syncTabs,syncTabs.length);
I got :
SyncTabs , Object[0] , 7 (for example)

And in the mean time the bug that I thought occurred because of the
alleged array corruption got fixed because I rewrote some of the stuff .

Thanks to everyone who took a look at the problem . The moral of the
story : don't believe console.log about Objects printed before the
dev-tools are opened.

On 11/10/2013 05:37 PM, Scott Fujan wrote: