[FIXED] Why doesn't a callback get executed immediately upon calling yield in Scrapy?

Issue

I am building a web scraper to scrape remote jobs. The spider behaves in a way that I don't understand and I'd appreciate it if someone could explain why.

Here's the code for the spider:

import scrapy
import time

class JobsSpider(scrapy.Spider):
    name = "jobs"
    start_urls = [
        "https://stackoverflow.com/jobs/remote-developer-jobs"
    ]
    already_visited_links = []

    def parse(self, response):
        jobs = response.xpath("//div[contains(@class, 'job')]")
        links_to_next_pages = response.xpath("//a[contains(@class, 's-pagination--item')]").css("a::attr(href)").getall()

        # visit each job page (as I do in the browser) and scrape the relevant information (Job title etc.)
        for job in jobs:
            job_id = int(job.xpath('@data-jobid').extract_first()) # there will always be one element
            # now visit the link with the job_id and get the info
            job_link_to_visit = "https://stackoverflow.com/jobs?id=" + str(job_id)
            request = scrapy.Request(job_link_to_visit,
                             callback=self.parse_job)
            yield request

        # sleep for 10 seconds before requesting the next page
        print("Sleeping for 10 seconds...")
        time.sleep(10)

        # go to the next job listings page (if you haven't already been there)
        # not sure if this solution is the best since it has a loop which has a recursion in it
        for link_to_next_page in links_to_next_pages:
            if link_to_next_page not in self.already_visited_links:
                self.already_visited_links.append(link_to_next_page)
                yield response.follow(link_to_next_page, callback=self.parse)

        print("End of parse method")

    def parse_job(self, response):
        print(response.body)
        print("Sleeping for 10 seconds...")
        time.sleep(10)
        pass

Here's the output (the relevant parts):

Sleeping for 10 seconds...
End of parse method
2021-04-29 20:49:55 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=525754> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:49:55 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=525748> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:49:55 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=497114> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:49:55 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=523136> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:49:55 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=525730> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
In parse_job
2021-04-29 20:50:05 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs/remote-developer-jobs?so_source=JobSearch&so_medium=Internal> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:05 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=523319> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:05 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=522480> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:05 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=511761> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:06 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=522483> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:06 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=249610> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
2021-04-29 20:50:06 [scrapy.core.engine] DEBUG: Crawled (200) <GET https://stackoverflow.com/jobs?id=522481> (referer: https://stackoverflow.com/jobs/remote-developer-jobs)
In parse_job
In parse_job
In parse_job
In parse_job
...

I don't understand why the parse method gets executed fully before the parse_job method gets called. From my understanding, as soon as I yield a job from jobs, the parse_job method should get called. The spider should go over each page of job listings and visit the details of each individual job at that job listing page. However, the description I gave in the previous sentence doesn't match the output. I also don't understand why are there multiple GET requests between each call to the parse_job method.

Can someone explain what is going on here?

Solution

Scrapy is event driven. Firstly requests are queued by Scheduler. Queued requests are passed to Downloader. The callback function is called when the response is downloaded and ready and then, response will be passed as the first argument to the callback function.

You are blocking callbacks by using time.sleep(). In the presented logs, after the first callback call the procedure was blocked for 10 seconds in parsed_job() but at the same time Downloader was working and getting responses ready for callback function as it is obvious in successive DEBUG: Crawled (200) logs after the first parse_job() call. So, while callback was blocked, Downloader finished its job and the responses were queued to be fed to callback function. As it is obvious in the last part of the logs, passing response to callback function was bottle necked.

If you want to put delay between requests, it's better to use DOWNLOAD_DELAY settings instead of time.sleep().

Take a look at this for more details about Scrapy architecture.

Answered By - Pouya Esmaeili