#345984: Client-side caching of administration menu unveiled a strange bug in D7 core (only):

Occasionally, but sometimes also permanently, AJAX/AHAH requests invoked by Drupal behaviors

  • are shown only once in Firebug's Console
  • are hitting the web server twice; only visible in the server's access log
  • are not cached by the browser.

This means, the same script/logic that works fine in D5/D6 shows this misbehavior in D7. (yes, I know the update docs.)

While client-side caching for admin_menu was the trigger, I was able to replicate this bug on user/1/edit, where system.js performs an AJAX request to auto-detect and update the user's timezone.

Again, Firebug just displays one request, but Apache's access log contains two immediately following requests for the same URL.

Also, the functionality and remaining behavior of Drupal works fine, i.e.: no errors, nothing.

This is critical, because this bug means that

  1. doubled server-load for such requests
  2. AJAX requests are not cached, even when their response contains explicit headers to do so.

Comments

sun’s picture

sun
Primary language German
Location Karlsruhe
commented
Issue tags: +JavaScript

.

quicksketch’s picture

quicksketch
he/him
commented

Sounds sort of similar to #137724: Empty Favicon (shortcut icon) Causes Duplicate Page Requests, perhaps a regression bug?

sun’s picture

sun
Primary language German
Location Karlsruhe
commented

Example access log entries:

192.168.0.2 - - [30/Mar/2009:16:31:20 +0200] "GET /user/1/edit HTTP/1.1" 200 50985
192.168.0.2 - - [30/Mar/2009:16:31:21 +0200] "GET /modules/user/user.js?7 HTTP/1.1" 200 6033
192.168.0.2 - - [30/Mar/2009:16:31:21 +0200] "GET /sites/all/modules/admin_menu/admin_menu.js?7 HTTP/1.1" 200 5375
192.168.0.2 - - [30/Mar/2009:16:31:21 +0200] "GET /misc/timezone.js?7 HTTP/1.1" 200 2660
192.168.0.2 - - [30/Mar/2009:16:31:22 +0200] "GET /?q=system%2Ftimezone%2F0%2F7200%2F1&date=Mon+Mar+30+2009+16%3A31%3A22+GMT%2B0200 HTTP/1.1" 200 15
192.168.0.2 - - [30/Mar/2009:16:31:22 +0200] "GET /?q=system%2Ftimezone%2F0%2F7200%2F1&date=Mon+Mar+30+2009+16%3A31%3A22+GMT%2B0200 HTTP/1.1" 200 15

Note that /?q=system%2Ftimezone%2F0%2F7200%2F1&date=Mon+Mar+30+2009+16%3A31%3A22+GMT%2B0200 shows only once in Firebug.

My (wild) guess would be one out of the following:

- HTTP response headers of Drupal are broken

- $.ajax() in jQuery 1.3 is broken

- Drupal.behaviors are broken

damien tournoud’s picture

damien tournoud commented
Status: Active » Postponed (maintainer needs more info)

Can't reproduce, at all.

sun’s picture

sun
Primary language German
Location Karlsruhe
commented

- Searched the net for some time, no results.

- Out of curiosity, commented out all stuff in .htaccess (especially new favicon handling in d7), no difference.

- I can replicate this bug in different browsers: Firefox 3.0 and IE6, both on Windows.

- Placed a console.log() into Drupal.behaviors.setTimezone.attach(), only triggered once.

- I can assure that virtual host configuration for d6 and d7 sites are identical.

Server software: Apache/2.2.11 (Win32) PHP/5.2.4

quicksketch’s picture

quicksketch
he/him
commented

sun, exactly how can we reproduce this? Does it happen with the core poll.module "more" button or with upload.module? From the original issue description, it sounds like #345984 is what caused the problem not that its affected by an existing problem.

sun’s picture

sun
Primary language German
Location Karlsruhe
commented
Status: Postponed (maintainer needs more info) » Closed (won't fix)

Sorry, this is too fuzzy for the moment. Just to be sure, I disabled admin_menu and was still able to replicate this issue with vanilla Drupal core. Both in Firefox and IE6.

However, I then disabled Firebug (in Firefox), and it suddenly no longer happened (also in IE). Searching for Firebug instead of jQuery made me finally find http://groups.google.com/group/firebug/browse_thread/thread/9e9da468ee5d.... It also no longer happens after updating Firebug to 1.3.3 (also not in IE).

The weird thing is that it only ever happened on my Drupal 7 test sites, regardless of the browser.

Weird.

Sorry for the noise.

---

With plain Drupal core, just visiting user/1/edit showed me...

in Firebug's Console:

GET http://drupal.test/?q=system%2Ftimezone%2F0%2F7200%2F1&date=Tue+Mar+31+2009+08%3A14%3A01+GMT%2B0200  200 OK 500ms

in Apache's access log:

192.168.0.2 - - [31/Mar/2009:08:14:00 +0200] "GET /user/1/edit HTTP/1.1" 200 50761
192.168.0.2 - - [31/Mar/2009:08:14:01 +0200] "GET /?q=system%2Ftimezone%2F0%2F7200%2F1&date=Tue+Mar+31+2009+08%3A14%3A01+GMT%2B0200 HTTP/1.1" 200 15
192.168.0.2 - - [31/Mar/2009:08:14:02 +0200] "GET /?q=system%2Ftimezone%2F0%2F7200%2F1&date=Tue+Mar+31+2009+08%3A14%3A01+GMT%2B0200 HTTP/1.1" 200 15