yourlabs / django-autocomplete-light

A fresh approach to autocomplete implementations, specially for Django. Status: v4 alpha, v3 stable, v2 & v1 deprecated.
https://django-autocomplete-light.readthedocs.io
MIT License
1.79k stars 467 forks source link

Website broke. Stuck understanding why. DAL not rendering. #1232

Closed bernd-wechner closed 3 years ago

bernd-wechner commented 3 years ago

For reference:

$ pip show django
Name: Django
Version: 3.1.7
Summary: A high-level Python Web framework that encourages rapid development and clean, pragmatic design.
Home-page: https://www.djangoproject.com/
Author: Django Software Foundation
Author-email: foundation@djangoproject.com
License: BSD-3-Clause
Location: /data/venv/CoGs/lib/python3.8/site-packages
Requires: pytz, asgiref, sqlparse
Required-by: django-url-filter, django-timezone-field, django-reset-migrations, django-mapbox-location-field, django-debug-toolbar, django-cuser, django-bitfield

$ pip show django-autocomplete-light
Name: django-autocomplete-light
Version: 3.8.2
Summary: Fresh autocompletes for Django
Home-page: http://django-autocomplete-light.rtfd.org
Author: James Pic
Author-email: jamespic@gmail.com
License: MIT
Location: /data/venv/CoGs/lib/python3.8/site-packages
Requires: six
Required-by: 

Has worked fine forever, just topped wotking and I'm stuck working out what change may have caused this. Unfortunately the nature of the problem is hard to apply change detection to, mainly because of poor publishing practices (which I'll look into fixing). You see it works fine on in the dev environment under runserver, but not when published to a live server.

When I load my page I get one single console error:

select2.js:5 Uncaught TypeError: $ is not a function
    at select2.js:5
    at select2.js:122
(anonymous) @ select2.js:5
(anonymous) @ select2.js:122

There are also two identical warnings (as I have two DAL widgets on this page I guess):

autocomplete_light.js:161 Your custom DAL function "select2" uses a deprecated event listener that will be removed in future versions. https://django-autocomplete-light.readthedocs.io/en/master/tutorial.html#overriding-javascript-code
initialize @ autocomplete_light.js:161
each @ jquery.js:354
each @ jquery.js:189
(anonymous) @ autocomplete_light.js:176
mightThrow @ jquery.js:3534
process @ jquery.js:3602
setTimeout (async)
(anonymous) @ jquery.js:3640
fire @ jquery.js:3268
add @ jquery.js:3327
(anonymous) @ jquery.js:3660
Deferred @ jquery.js:3751
then @ jquery.js:3645
jQuery.fn.ready @ jquery.js:3840
(anonymous) @ autocomplete_light.js:175
(anonymous) @ autocomplete_light.js:229
load (async)
(anonymous) @ autocomplete_light.js:30
09:26:29.754 

The header of the page renders in code as:

<!DOCTYPE html>
<html>
<head>
    <title>New Player</title>
    <link rel="stylesheet" type="text/css" href="/static/CoGs/css/default.css" />
    <link rel="icon" href="/static/favicon.ico">
    <meta name="robots" content="NONE,NOARCHIVE" />
    <meta charset="UTF-8" />
    <link rel="stylesheet" type="text/css" href="/static/CoGs/css/tooltip.css" />
    <script src="https://cdnjs.cloudflare.com/ajax/libs/jquery/3.3.1/jquery.js"></script>
        <!-- START DAL media -->
        <link href="/static/admin/css/vendor/select2/select2.css" type="text/css" media="screen" rel="stylesheet">
<link href="/static/admin/css/autocomplete.css" type="text/css" media="screen" rel="stylesheet">
<link href="/static/autocomplete_light/select2.css" type="text/css" media="screen" rel="stylesheet">
<script src="/static/admin/js/vendor/select2/select2.full.js"></script>
<script src="/static/autocomplete_light/autocomplete_light.js"></script>
<script src="/static/autocomplete_light/select2.js"></script>
<script src="/static/autocomplete_light/i18n/en.js"></script>
        <!-- END DAL media -->

    <link rel="stylesheet" type="text/css" href="https://cdnjs.cloudflare.com/ajax/libs/select2-bootstrap-theme/0.1.0-beta.10/select2-bootstrap.min.css">
    <script>$.fn.select2.defaults.set( "theme", "bootstrap" );</script>

    <script src="https://cdnjs.cloudflare.com/ajax/libs/jqueryui/1.12.1/jquery-ui.js"></script>
    <link rel="stylesheet" type="text/css" href="https://cdnjs.cloudflare.com/ajax/libs/jqueryui/1.12.1/jquery-ui.css"/ >

    <script src="https://cdnjs.cloudflare.com/ajax/libs/jquery-datetimepicker/2.5.20/jquery.datetimepicker.full.js"></script>
    <script src="https://cdnjs.cloudflare.com/ajax/libs/underscore.js/1.12.0/underscore-min.js"></script>   

    <link rel="stylesheet" type="text/css" href="https://cdnjs.cloudflare.com/ajax/libs/jquery-datetimepicker/2.5.20/jquery.datetimepicker.css"/ >
    <script>
        const datetime_format = "Y-m-d H:i:sO";
    </script>

    <script src="/static/CoGs/js/jstz.min.js"></script>
    <script src="/static/CoGs/js/datetime_functions.js"></script>

The message looks familiar and suggests to me JQuery hasn't loaded or loaded twice ... but I find no evidence of that.

Aside from solving the problem, what I'm for is to learn better how to interpret it and assess the cause if possible.

This has killed my website alas. So I'll double down and try rollbacks to see what happens, but alas it's a pre-beta site (albeit in use as an alpha) and so robust backup systems aren't in place yet. Oh well.

The mystery I have is that I can load this page under runserver on a development machine and it renders fine, published live it does not. And a context diff between he two rendered pages has no significant differences:

*** dev.html    2021-04-04 10:13:39.684934559 +1000
--- live.html   2021-04-04 10:12:21.769155148 +1000
***************
*** 55,61 ****

    <script>
        // Template provided variables that submit_info.js expects.
!       const CSRF_field    = '<input type="hidden" name="csrfmiddlewaretoken" value="iNMsdCwG5kp6I7WxsQ8kUuEzSYDcE0oSDleJh2SAjM1SdgPgQl22NNXImt57LkTT">';
        const POST_RECEIVER = "/post/clientinfo";
        const SESSION_timezone = "Australia/Hobart";
        const SESSION_utcoffset = "600";
--- 55,61 ----

    <script>
        // Template provided variables that submit_info.js expects.
!       const CSRF_field    = '<input type="hidden" name="csrfmiddlewaretoken" value="DVm4cxAFtsWrKJ3bhHvfjYCLJLxehmMh2uCYw6nXfVpGqEGLycqVaBcGCIhZhePj">';
        const POST_RECEIVER = "/post/clientinfo";
        const SESSION_timezone = "Australia/Hobart";
        const SESSION_utcoffset = "600";
***************
*** 137,143 ****
            <div id="branding">
                <a href="/static/logo.png"><img src="/static/logo.png" align=left height=70></a>

!               <h1 id="site-name"><a href="/">CoGs Development</a></h1>
            </div>

--- 137,143 ----
            <div id="branding">
                <a href="/static/logo.png"><img src="/static/logo.png" align=left height=70></a>

!               <h1 id="site-name"><a href="/">CoGs Live</a></h1>
            </div>

***************
*** 211,217 ****
  <form id="formData" action="" method="post">

!   <input type="hidden" name="csrfmiddlewaretoken" value="iNMsdCwG5kp6I7WxsQ8kUuEzSYDcE0oSDleJh2SAjM1SdgPgQl22NNXImt57LkTT">
    <table>
        <tr>
--- 211,217 ----
  <form id="formData" action="" method="post">

!   <input type="hidden" name="csrfmiddlewaretoken" value="DVm4cxAFtsWrKJ3bhHvfjYCLJLxehmMh2uCYw6nXfVpGqEGLycqVaBcGCIhZhePj">
    <table>
        <tr>
***************
*** 352,367 ****

    <input type="submit" value="Submit" style="margin-top:20px;"/>

-       <br>
-       <br><input type="checkbox" id="debug_post_data" name="debug_post_data" value="on"> Display POST data only (do not process submission)
-       <br><input type="checkbox" id="debug_form_data" name="debug_form_data" value="on"> Display form data only (do not process submission)
-       <br><input type="checkbox" id="debug_rebuild_request" name="debug_rebuild_request" value="on"> Display rebuild request log only (do not save anything to database)
-       <br><br>
-       <div class='tooltip'>
-           <input type="button" value="Prepare Submission" id="prepare_submission"/>
-           <span class='tooltiptext' style='width: 300%;'>Runs the OnSubmit event handler without submitting. So the page can be inspected in its state just prior to submission.</span>
-       </div>
- 
  </form>
***************
*** 449,455 ****
            <th>Value</th>
            <th rowspan=0 valign=top>
                <form  action="/post/clientinfo" method="post">
!                   <input type="hidden" name="csrfmiddlewaretoken" value="iNMsdCwG5kp6I7WxsQ8kUuEzSYDcE0oSDleJh2SAjM1SdgPgQl22NNXImt57LkTT">
                    <input type="hidden" name="clear_session" value="1">
                    <button type="submit">Clear Session</button>
                </form>
--- 439,445 ----
            <th>Value</th>
            <th rowspan=0 valign=top>
                <form  action="/post/clientinfo" method="post">
!                   <input type="hidden" name="csrfmiddlewaretoken" value="DVm4cxAFtsWrKJ3bhHvfjYCLJLxehmMh2uCYw6nXfVpGqEGLycqVaBcGCIhZhePj">
                    <input type="hidden" name="clear_session" value="1">
                    <button type="submit">Clear Session</button>
                </form>
***************
*** 466,472 ****

            <tr><td valign=top>_auth_user_backend</td><td>django.contrib.auth.backends.ModelBackend</td></tr>

!           <tr><td valign=top>_auth_user_hash</td><td>e32364665e0276ad0baeac1b2ecaa9823715ad76c59184de3cef496cfd89b5d6</td></tr>

            <tr><td valign=top>preferred_league</td><td>1</td></tr>

--- 456,462 ----

            <tr><td valign=top>_auth_user_backend</td><td>django.contrib.auth.backends.ModelBackend</td></tr>

!           <tr><td valign=top>_auth_user_hash</td><td>65e9044d38a16b07fe7bd5663cfee89b26b35ca6ce33cb103ac8ea2d9b71c06c</td></tr>

            <tr><td valign=top>preferred_league</td><td>1</td></tr>

Same results in same browser, and also browser independent. Something has broken on the live site, that I am having seriously trouble understanding and yet it seems to be pure Javascript issues, and identical Javascript.

I even did a meld on the static directory under runserver and on the live side, and they are identical, and I run collectstatic as I always have on each side sensibly.

bernd-wechner commented 3 years ago

Still stuck on this. It was working so well until just recently, now some JS issue on live site only, and I can't find any differences yet in the live and dev site includes and sources or code delivered. Must be there somewhere. And smells like failed or double load of JQuery problem.

bernd-wechner commented 3 years ago

More diagnostics.

These code snippets:

    context['Django_source'] = django.__spec__.origin  # @UndefinedVariable
    context['Django_version'] = django.__version__

    context['DAL_source'] = dal.__spec__.origin  # @UndefinedVariable
    context['DAL_version'] = get_distribution("django-autocomplete-light").version
    <pre id="version_debug_info">
    Django source: {{ Django_source }}
    Django version: {{ Django_version }}
    DAL source: {{ DAL_source }}
    DAL version: {{ DAL_version }}
    </pre> 
    <script>
        const v1 = jQuery.fn.jquery;
        const v2 = $().jquery;
        const e = document.getElementById("version_debug_info");
        e.innerText = e.innerText + "JQuery fn version: " + v1 + "\n\tJQuery $ version: " + v2;
    </script>

Yield identical output on my page, on the functional (dev) and dysfunctional (live) sites (bar the source paths as the venv is in a different spot)

    Django source: /data/venv/CoGs/lib/python3.8/site-packages/django/__init__.py
    Django version: 3.1.7
    DAL source: /data/venv/CoGs/lib/python3.8/site-packages/dal/__init__.py
    DAL version: 3.8.2
    JQuery fn version: 3.3.1
    JQuery $ version: 3.3.1

This snippet in settings.py

log.debug(f"Django settings: {'Live' if SITE_IS_LIVE else 'Development'} Server")
log.debug(f"Django version: {django.__version__}")
log.debug(f"Django loaded from: {django.__file__}")
log.debug(f"Using Path: {sys.path}")
log.debug(f"Process Info: {pinfo()}")
log.debug(f"Static root: {STATIC_ROOT}")
log.debug(f"Static file dirs: {locals().get('STATICFILES_DIRS', globals().get('STATICFILES_DIRS', []))}")
log.debug(f"Debug: {DEBUG}")

produces for the live site:

Django settings: Live Server
Django version: 3.1.7
Django loaded from: /data/venv/CoGs/lib/python3.8/site-packages/django/__init__.py
Using Path: ['.', '', '/usr/lib/python38.zip', '/usr/lib/python3.8', '/usr/lib/python3.8/lib-dynload', '/data/venv/CoGs/lib/python3.8/site-packages', '/home/sting/.local/lib/python3.8/site-packages', '/usr/local/lib/python3.8/dist-packages', '/usr/lib/python3/dist-packages']
Process Info: {'Me': "pid=1653007, name=uwsgi, commandline=['/usr/bin/uwsgi', '--ini', '/usr/share/uwsgi/conf/default.ini', '--ini', '/etc/uwsgi/apps-enabled/leaderboard.space.ini', '--daemonize', '/var/log/uwsgi/app/leaderboard.space.log'], started=1617543085.49", 'My Parent': "pid=1, name=systemd, commandline=['/lib/systemd/systemd', '--system', '--deserialize', '31'], started=1605235057.38"}
Static root: /data/www/leaderboard.space/static/
Static file dirs: []
Debug: True

And similar on the Development site, with local filesystem differences.

The symptoms are that I have a DAL widget that rends like this on the Development machine:

image

and if I click in the white box I get a drop down, correctly populated by a callback. (i.e. it works as it has for eyars and is fine). The console is clear on the browser. On the live site as of this weekend (with unknown changes causing it) I see this:

image

And this on the console:

select2.js:5 Uncaught TypeError: $ is not a function
    at select2.js:5
    at select2.js:122

and select2.js is found at:

https://my.site/static/autocomplete_light/select2.js

as revealed in the browser debugger hovering over the above message.

All these diags so far are barking up the wrong tree I worry. And I am still clueless as to cause.

bernd-wechner commented 3 years ago

Aaargh, am pulling my hair out here. Have salvaged a path forwards but still don't understand it. Single stepping JS code on the live site I find yl.JQuery is never defined. I see if it defined in jquery.init.js so I add this to the template:

<script src="/static/autocomplete_light/jquery.init.js"></script>

and suddenly all works again.

Digging deeper, I found that something did go wrong with collectstatic. The file select2.js was different between the two servers. I cleaned static and collected again and all came good once more.

Oh the hours that cost me!

gamesbook commented 3 years ago

Digging deeper, I found that something did go wrong with collectstatic.

How is this possible? collectstatic is a well-established Django function that has been running for years.

bernd-wechner commented 3 years ago

No idea. Hard to diagnose ... I run a script to publish for dev to live, and it stops copies across the site code, then runs collectstatic and reloads uwsgi. Been working fine for a long time.

My best theory (and it is but a theory), is that somehow somewhen, I did something kludgy by hand (put a wrong file in /staticautocomplete_light/select2.js - and this is one heck of a tenuous theory as I cannot for love or money imagine ever doing something so bizarre and esoteric) and collectstatic I was not using with --clean and so it wasn't copying the right select2.js into static. In short one manual error is preserved by collectstatic.

So my fix now has been to put --clean in the publish script when it runs collectstatic and all seems well. Did some tests, by hand to confirm behaviours and pretty happy.

I have one odd behaviour (that I sort of like but haven't found documented anywhere). I keep images (icons and such), javascript source, and css files in an app folder in a fairly prosaic layout:

app\static
    css
    img
    js

And the file in img and only those, end up the /static folder after a collectstatic (as well as under static\app\img). So I'm not convinced I've found the definitive documentation on collectstatic yet though I've read a lot ;-). I might even dig into its code at some point (that of colectstatic).

It's certainly been reliable yes for years. Hence my tenuous theory, of some manual miscopy of a select.js file that was subsequently respected by collectstatic without --clean. That manual glitch must have happened in the last month or so (as data entry is a monthly routine on it currently and happened last month with working forms).

But yes, when I said "something did go wrong with collectstatic" I did mean in fact with my use of it, rather than with its code (which is indeed mature, stable and in the venv site-packages folder).