I don't seem to be be able to run a background task.

I invoke the background process as so...

 $handle = background_process_start('my_background_probe');

I have a function in my module defined

function my_background_probe()
{
  debug('my_background_probe');
}

In the config/overview for background process I can see my created processes...

But I don't see "my_background_probe" in the logs.

Any ideas?

Is there a complete example somewhere?

Can you call debug() from inside a background process?

I am running with Drupal 7/Microsoft Web Platform PHP IIS7.5 and SQL 2008.

Thanks.

Comments

gielfeldt’s picture

gielfeldt commented

Hi

You can call debug() from within a background process. It will only log to watchdog of course, and not the screen. The above code works for me. But if you say you can see your process in the config overview, i suspect the process is never started at all, as it should be removed again almost instantaneously when it finishes.

Are there any logs from Background Process in watchdog?

Also, did you configure background process in settings.php? If not, try to go to admin/config/system/background-process and click "Determine default service host" and let me know what it reports.

DrMiaow’s picture

DrMiaow commented

Thanks for the quick reply.

Testing it now under Aquia drupal. Getting the same behavior.

It reports

Default service host determined at http://localhost:8082

Which is what it also said when the module was first installed.

I see no log messages from the background process in http://localhost:8082/admin/reports/

I see a log message from before and after my call to background_process_start('my_background_probe'); but I don't see any sign of the debug('my_background_probe'); in the logs.

gielfeldt’s picture

gielfeldt commented

Strange. If the default service host determination works, then the background_process_start() should work as well, as they use the same mechanism.

I'll have to think more about this to develop a theory.

Do you get any errors in your webserver logs? Do you see any requests to urls containing 'bgp:start' in your access logs?

DrMiaow’s picture

DrMiaow commented

Found this. Any help?

[Mon Mar 19 16:50:12 2012] [error] [client 127.0.0.1] (20024)The given path is misformatted or contained invalid characters: Cannot map POST /bgp%3Astart/10b1047ea5291c445891e1177ec8a325/444a288fa091e359ca3d8294f1957916 HTTP/1.0 to file, referer: http://localhost:8082/admin/content/tracks/add?render=overlay
[Mon Mar 19 16:52:39 2012] [error] [client 127.0.0.1] (20024)The given path is misformatted or contained invalid characters: Cannot map POST /bgp%3Astart/719e72ce6130b8e8209e514c4144e1df/1b7707f3d36732cb9b1d2df64caef525 HTTP/1.0 to file, referer: http://localhost:8082/admin/content/tracks/add?render=overlay
[Mon Mar 19 17:01:36 2012] [error] [client 127.0.0.1] (20024)The given path is misformatted or contained invalid characters: Cannot map POST /bgp%3Astart/16954c4566aada54848cb799097407c1/97354a070dfcec88ba756c89fe7f097e HTTP/1.0 to file, referer: http://localhost:8082/admin/content/tracks/add
[Mon Mar 19 17:22:03 2012] [error] [client 127.0.0.1] (20024)The given path is misformatted or contained invalid characters: Cannot map POST /bgp%3Astart/1102796a40155aa94b6d1a5431872124/6c35233666ace644604347c4da88305b HTTP/1.0 to file, referer: http://localhost:8082/admin/content/tracks/add?render=overlay

gielfeldt’s picture

gielfeldt commented

ahhh ... crap. Using colon in an URL is not to IIS friendly.

You might be able to configure your webserver to accept it though (via web.config): http://stackoverflow.com/questions/667429/using-a-colon-in-a-url-with-as...

I'll change the colon (if possible). I'll let you know when or if. Then you can try out the 7.x-dev version. I don't know when I'll get the time though, so let me know if it's possible to apply the IIS "fix".

gielfeldt’s picture

gielfeldt commented

Also if you're up for it, you can try to replace all 'bgp:' with e.g. 'bgp-' and post a patch to me.

DrMiaow’s picture

DrMiaow commented

That log is from Apache running under Windows using Acquia, but I get the same result.

After a rename and re-install of the module I get errors in debug log

TYPE	bg_process
DATE	Monday, March 19, 2012 - 15:34
USER	Anonymous (not verified)
LOCATION	http://localhost/bgp-start/44b3b5e884c9bdbb14aa6858a0fce8b3/725a0423ee3846e5bb0fd1a1e6184694
REFERRER	http://localhost:8082/admin/content/tracks/add?render=overlay
MESSAGE	Unknown process: 44b3b5e884c9bdbb14aa6858a0fce8b3
SEVERITY	notice
HOSTNAME	127.0.0.1
OPERATIONS	
TYPE	 access denied
DATE	Monday, March 19, 2012 - 15:34
USER	Anonymous (not verified)
LOCATION	http://localhost/bgp-start/44b3b5e884c9bdbb14aa6858a0fce8b3/725a0423ee3846e5bb0fd1a1e6184694
REFERRER	http://localhost:8082/admin/content/tracks/add?render=overlay
MESSAGE	bgp-start/44b3b5e884c9bdbb14aa6858a0fce8b3/725a0423ee3846e5bb0fd1a1e6184694
SEVERITY	warning
HOSTNAME	127.0.0.1
OPERATIONS
gielfeldt’s picture

gielfeldt commented

That's odd. I'm not sure these errors are related though. Could try clearing cache, and then make sure the background process table is clear, and then run your code again?

DrMiaow’s picture

DrMiaow commented

Cleared cache.
http://localhost:8082/admin/config/system/background-process/overview shows nothing.
background_process table is empty.
Same result.

I started hacking around in the code.

Looks like some kind of caching issue/race condition with writing and reading the database. The incoming request to bgp-start fails to find the process in the table. ( background_process_get_process seems to fail find the process by it's handle value, despite it being in the database. )

BUT!

If I repeat the request (cut and paste from logs) , then the process fires.

So it seems that timing is important... I have verified that $handle was identical in both calls.

Logging in 'newest first' order

After I paste in the URL background_process_get_process: b1627fcd1822c530806918726866f205

bg_process	03/20/2012 - 03:18	FOUND	admin	
bg_process	03/20/2012 - 03:18	background_process_get_process:...	admin

The original attempt. background_process_get_process: b1627fcd1822c530806918726866f205

access denied	03/20/2012 - 03:15	bgp-start/b1627fcd1822c530806918726866f205...	Anonymous (not verified)	
bg_process	03/20/2012 - 03:15	Unknown process: b1627fcd1822c530806918726866f205	Anonymous (not verified)	
bg_process	03/20/2012 - 03:15	NOT FOUND	Anonymous (not verified)	
php	03/20/2012 - 03:15	User notice: false in background_process_get_process(...	Anonymous (not verified)	
bg_process	03/20/2012 - 03:15	background_process_get_process:...	Anonymous (not verified)	
bg_process	03/20/2012 - 03:15	background_process_http_request_initiate Array	admin	
bg_process	03/20/2012 - 03:15	background_process_http_request $host localhost:8082	admin	
bg_process	03/20/2012 - 03:15	background_process_http_request $urlhttp://localhost...	admin	
bg_process	03/20/2012 - 03:15	background_process_set_process:...	admin	
bg_process	03/20/2012 - 03:15	background_process_lock_process:...	admin	
bg_process	03/20/2012 - 03:15	NOT FOUND	 admin	
bg_process	03/20/2012 - 03:15	background_process_get_process:...	admin

I added some logging to background_process_get_process to track when it was finding it...

**
 * Get background process
 *
 * @param $handle
 *   Handle of background process
 * @return object
 *   Background process
 */
function background_process_get_process($handle) {

	watchdog('bg_process', 'background_process_get_process: %handle', array('%handle' => $handle));


  $result = db_select('background_process', 'bp')
    ->fields('bp', array('handle', 'callback', 'args', 'uid', 'token', 'service_host', 'start', 'status'))
    ->condition('handle', $handle)
    ->execute()
    ->fetchObject();
	
  debug($result);
	
  if ($result) {
	watchdog('bg_process', 'FOUND');
  
    $result->args = unserialize($result->args);
    $result->callback = unserialize($result->callback);
    $result->start = $result->start ? $result->start : $result->start;
    return $result;
  }
  
  watchdog('bg_process', 'NOT FOUND');
  
  return FALSE;
}
gielfeldt’s picture

gielfeldt commented

The plot thickens ... Are you using INNODB with AUTOCOMMIT=0 and REPEATABLE_READ isolation level?

DrMiaow’s picture

DrMiaow commented

Looks like autocommit = 1

Variable_name	Value
tx_isolation	REPEATABLE-READ
auto_increment_increment	1
auto_increment_offset	1
autocommit	ON
automatic_sp_privileges	ON
innodb_autoextend_increment	8
innodb_autoinc_lock_mode	1
sql_auto_is_null	ON
gielfeldt’s picture

gielfeldt commented

Hmmm, weeeeeird. I'll be back...

gielfeldt’s picture

gielfeldt commented

Would be possible for you to do a:

ALTER TABLE background_process ENGINE=MYISAM;

Just to check if it's the InnoDB transactions/isolation level that's the culprit.

DrMiaow’s picture

DrMiaow commented

That seemed to do the trick.

gielfeldt’s picture

gielfeldt commented

Interesting. Do you know if you're inside a transaction (manually started or otherwise), when you launch the background process?

Btw, I'll fix the url-stuff soon and post here when I've committed to dev.

DrMiaow’s picture

DrMiaow commented

Thanks.

I am creating the background process in an implementation of hook_node_presave.

I don't know if Drupal calls that while in a transaction, but it is plausible. It would certainly explain what I am seeing.

gielfeldt’s picture

gielfeldt commented

It's very plausible. I see 2 solutions:

1.) change the engine for background_process table to e.g. MyISAM.
2.) use a different connection for the background_process table if inside a transaction.

Thoughts?

DrMiaow’s picture

DrMiaow commented

1) Wont work consistently. (MSSQL etc.).
2) Yes. That would work and not have too much of a side-effect (other than database load).

also

3) Defer the creation of the background process till we are out of scope of the transaction, like at the end of the request? reliability if there was an error between the declaring our intention to create the process and the and of the request where we add it to the database.

gielfeldt’s picture

gielfeldt commented

I though about the deferring as well, but that's just going to give me more problems than benefits, I suspect.

I'll think I'll look into number 2) as you are right about 1). My question in #18 almost seemed rhetorical after reading it again :-)

gielfeldt’s picture

gielfeldt commented

Use of different connection for background processes has been committed to dev.

The easiest way to make use of it, is to add the following to settings.php right after your $databases definition (php tags included for syntax highlighting only):

<?php
$databases['background_process'] = $databases['default'];
?>
gielfeldt’s picture

gielfeldt commented
Status: Active » Fixed

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.