Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-31410

PayPal IPN Script exposed to message_send() failure

    Details

    • Database:
      Any
    • Testing Instructions:
      Hide

      1/ regression test - test that paypal work as before
      2/ access the paypal directly and verify there is no error message any more and 200 http code is returned
      3/ hack your message_send to always fail and verify it does not affect the plugin apart from error messages in logs and email not delivered (you need to repeat the enrolments a few times)

      Show
      1/ regression test - test that paypal work as before 2/ access the paypal directly and verify there is no error message any more and 200 http code is returned 3/ hack your message_send to always fail and verify it does not affect the plugin apart from error messages in logs and email not delivered (you need to repeat the enrolments a few times)
    • Difficulty:
      Easy
    • Affected Branches:
      MOODLE_21_STABLE, MOODLE_24_STABLE, MOODLE_25_STABLE, MOODLE_26_STABLE, MOODLE_27_STABLE
    • Fixed Branches:
      MOODLE_24_STABLE, MOODLE_25_STABLE, MOODLE_26_STABLE
    • Pull from Repository:
    • Pull 2.6 Branch:
      w50_MDL-31410_m26_paypalipn
    • Pull Master Branch:
      w50_MDL-31410_m27_paypalipn
    • Sprint:
      BACKEND Sprint 7
    • Story Points (Obsolete):
      3
    • Sprint:
      BACKEND Sprint 7

      Description

      The below issue includes the resolution. It merely needs to be marked as fixed and merged in to the main development branch.

      The ipn.php script, that is a part of the Paypal enrolment method, makes calls to a function "message_send" that can cause the entire PayPal enrolment method to fail.

      The ipn script is called by PayPal when a payment has been processed. Paypal calls the script and passes various tokens regarding the transaction. The ipn script:

      1) Opens a handle for the paypal connection
      2) Evaluates the received tokens and validates them
      3) Enrols a student accordingly
      4) Notifies the student, instructors & admins via a call to "message_send()"
      5) Closes the connection from paypal

      Various people have been reporting that their paypal enrolments work fine for a while, but they start getting these IPN failure warning messages from Paypal. In their IPN history in Paypal, they see a list of failed transactions where the server (moodle) response was a 404.

      What's happening for these people, is the 4th step above is failing. The ipn script dies as a product of message_send() failing and the PHP server process would seem to time out and cause the web server to return a 404 to paypal. Since step 3 has been completed, end users of moodle are getting what they need from the plugin. However Paypal doesn't tolerate the 404 responses for long and automatically disables IPN messaging after a while - causing paypal enrolments to fail entirely.

      The solution I'm proposing is really simple. I've modified ipn.php to use a wrapper function for message_send that puts the call in try-catch block. This insulates the execution of ipn.php from whatever message_send failures ruining the whole experience. I believe resolving the issue in message_send is another matter (and may merely be a misconfiguration thing - though myself and others do have systems that send us emails successfully, guess those situations aren't depending on the same function).

      I've attached my modified version of ipn.php below. I hope it is immediately merged in to the main development branch as this is probably affecting even more people than have been complaining about it.

      This issue has been observed by me personally across a wide range of 2.x Moodle installations. I've avoided fixing it myself and have just run on weekly builds hoping someone else would fix it. But push came to shove thus I fixed it myself.

        Gliffy Diagrams

          Activity

          Hide
          jamessnell James Snell added a comment -

          This is my fixed version of ipn.php. All that's different is all previous calls to "message_send" have been changed to call a new function "attempt_message_send". The new function "attempt_message_send" just wraps calls to "message_send" in a try catch block and provides a means to output the messages to plain text file that admins can manually activate if they wish.

          Show
          jamessnell James Snell added a comment - This is my fixed version of ipn.php. All that's different is all previous calls to "message_send" have been changed to call a new function "attempt_message_send". The new function "attempt_message_send" just wraps calls to "message_send" in a try catch block and provides a means to output the messages to plain text file that admins can manually activate if they wish.
          Hide
          cfollin Chris Follin added a comment -

          message_send() is failing because the message provider for enrol/paypal was never installed. There is no enrol/paypal/db/messages.php file to install it, so any call to the messaging system from enrol/paypal won't work. This appears to be an oversight from when enrol/paypal was upgraded from 1.9 to 2.0.

          I created the messages.php file, bumped the version number of enrol/paypal and ran Notifications. That fixed the major problem. The IPN was successful, the notifications were sent to student, teacher, and admins; however, the messages look like a language string is missing so the messages aren't very useful to a user. As soon as I figure out what is still missing, I'll either attach patches here or create a new ticket.

          I also think that James' patch is a good idea. Even when the message provider issue is fixed, sending a message could still fail for other reasons. I cannot think of any reason why someone would want a failure to send the notification message to cause the whole IPN to fail, so insulating ipn.php from a message_send() failure is a good idea.

          Show
          cfollin Chris Follin added a comment - message_send() is failing because the message provider for enrol/paypal was never installed. There is no enrol/paypal/db/messages.php file to install it, so any call to the messaging system from enrol/paypal won't work. This appears to be an oversight from when enrol/paypal was upgraded from 1.9 to 2.0. I created the messages.php file, bumped the version number of enrol/paypal and ran Notifications. That fixed the major problem. The IPN was successful, the notifications were sent to student, teacher, and admins; however, the messages look like a language string is missing so the messages aren't very useful to a user. As soon as I figure out what is still missing, I'll either attach patches here or create a new ticket. I also think that James' patch is a good idea. Even when the message provider issue is fixed, sending a message could still fail for other reasons. I cannot think of any reason why someone would want a failure to send the notification message to cause the whole IPN to fail, so insulating ipn.php from a message_send() failure is a good idea.
          Hide
          jamessnell James Snell added a comment -

          Nice work Chris. Thank you for looking in to message_send. I would have if I'd personally cared, which I don't - as paypal tends to send notifications for payments received. Still, it's helpful to have that option.

          Thanks for complimenting my fix too. I suppose a different option is to leave it uninsulated and just close the connection to paypal before trying to do anything else. Either way, robust code "helps us play" (like "Iron". Also, "from now on, the baby sleeps in the crib").

          Show
          jamessnell James Snell added a comment - Nice work Chris. Thank you for looking in to message_send. I would have if I'd personally cared, which I don't - as paypal tends to send notifications for payments received. Still, it's helpful to have that option. Thanks for complimenting my fix too. I suppose a different option is to leave it uninsulated and just close the connection to paypal before trying to do anything else. Either way, robust code "helps us play" (like "Iron". Also, "from now on, the baby sleeps in the crib").
          Hide
          cfollin Chris Follin added a comment -

          For testing, one way to make sure that the IPN fails and a call to message_send() is made is to change the business email address on the Paypal enrollment settings page so that it does not match the address on file with Paypal. I posted a comment in MDL-30647 regarding that. We found that even a capitalization mismatch will cause the IPN to fail and it will then try to use message_send() (via message_paypal_error_to_admin()) to send a message about the failure to the admin.

          Show
          cfollin Chris Follin added a comment - For testing, one way to make sure that the IPN fails and a call to message_send() is made is to change the business email address on the Paypal enrollment settings page so that it does not match the address on file with Paypal. I posted a comment in MDL-30647 regarding that. We found that even a capitalization mismatch will cause the IPN to fail and it will then try to use message_send() (via message_paypal_error_to_admin()) to send a message about the failure to the admin.
          Hide
          cfollin Chris Follin added a comment -

          You're welcome, James.

          Please see MDL-31429 for a patch to fix message_send(), at least with regard to the message provider not being installed.

          Show
          cfollin Chris Follin added a comment - You're welcome, James. Please see MDL-31429 for a patch to fix message_send(), at least with regard to the message provider not being installed.
          Hide
          jamessnell James Snell added a comment -

          This ticket is ready to be closed as the issue is long since resolved in trunk.

          Show
          jamessnell James Snell added a comment - This ticket is ready to be closed as the issue is long since resolved in trunk.
          Hide
          skodak Petr Skoda added a comment -

          Thanks for the report and patch, I have used a bit different solution to ignore all exceptions in the ipn script.

          Show
          skodak Petr Skoda added a comment - Thanks for the report and patch, I have used a bit different solution to ignore all exceptions in the ipn script.
          Hide
          rajeshtaneja Rajesh Taneja added a comment -

          Thanks Petr,

          Patch looks spot-on.
          Before pushing for integration please consider:

          1. Creating branches for 24, 25 and 26
          2. Modify git commit message to include code area (enrol_paypal) http://docs.moodle.org/dev/Commit_cheat_sheet#Provide_clear_commit_messages
          Show
          rajeshtaneja Rajesh Taneja added a comment - Thanks Petr, Patch looks spot-on. Before pushing for integration please consider: Creating branches for 24, 25 and 26 Modify git commit message to include code area (enrol_paypal) http://docs.moodle.org/dev/Commit_cheat_sheet#Provide_clear_commit_messages
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -

          I'll be trying this tomorrow (Wed). I'm sure it's something in my end preventing the ipn verification to happen, just have to debug it a bit more. Other than that, code seems to be correct/has sense.

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - I'll be trying this tomorrow (Wed). I'm sure it's something in my end preventing the ipn verification to happen, just have to debug it a bit more. Other than that, code seems to be correct/has sense.
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -

          Yay, traced the problem down to initialise_fullme()/setup_get_remote_url() where my port mappings where leading to an exception there (non matching with wwwroot). That caused the ipn.php call to die before having any chance to perform the verification step.

          I don't quite understand why the same error does not happen when I browse the site, but who cares. Now I'm able to test it. Doing.

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - Yay, traced the problem down to initialise_fullme()/setup_get_remote_url() where my port mappings where leading to an exception there (non matching with wwwroot). That caused the ipn.php call to die before having any chance to perform the verification step. I don't quite understand why the same error does not happen when I browse the site, but who cares. Now I'm able to test it. Doing.
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -

          Ok, easy to test it with broken messaging because if the course has not a teacher, it's throwing both PHP warnings and exceptions. All them are nicely send to logs without stopping the ipn.php verification to proceed.

          So, the handler does its job:

          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Warning:  Creating default object from empty value in /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php on line 246
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Stack trace:
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP   1. {main}() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:0
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Notice:  Trying to get property of non-object in /Users/stronk7/git_moodle/integration/lib/messagelib.php on line 89
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Stack trace:
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP   1. {main}() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:0
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP   2. message_send() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:260
          [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] enrol_paypal IPN exception handler: Error writing to database Debug: Column 'useridfrom' cannot be null\nINSERT INTO mdl_message (useridfrom,useridto,subject,fullmessage,fullmessageformat,fullmessagehtml,smallmessage,notification,contexturl,contexturlname,timecreated) VALUES(?,?,?,?,?,?,?,?,?,?,?)\n[array (\n  0 => NULL,\n  1 => '5',\n  2 => 'New enrolment in PAYPAL25',\n  3 => 'Welcome to PAYPAL25!\n\nIf you have not done so already, you should edit your profile page so that we can learn more about you:\n\n  http://ci.stronk7.com:8787/~stronk7/integration/user/view.php?id=5',\n  4 => '2',\n  5 => '',\n  6 => '',\n  7 => 0,\n  8 => NULL,\n  9 => NULL,\n  10 => 1386810817,\n)]\nError code: dmlwriteexception\n* line 426 of /lib/dml/moodle_database.php: dml_write_exception thrown\n* line 1089 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()\n* line 1131 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()\n* line 206 of /lib/messagelib.php: call to mysqli_native_moodle_database->insert_record()\n* line 260 of /enrol/paypal/ipn.php: call to message_send()\n

          Note I'm adding a extra commit to solve both the PHP Warning and the problems with notifications when there is no teacher in the course.

          ... in progress ...

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - Ok, easy to test it with broken messaging because if the course has not a teacher, it's throwing both PHP warnings and exceptions. All them are nicely send to logs without stopping the ipn.php verification to proceed. So, the handler does its job: [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Warning: Creating default object from empty value in /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php on line 246 [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Stack trace: [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP 1. {main}() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:0 [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Notice: Trying to get property of non-object in /Users/stronk7/git_moodle/integration/lib/messagelib.php on line 89 [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP Stack trace: [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP 1. {main}() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:0 [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] PHP 2. message_send() /Users/stronk7/git_moodle/integration/enrol/paypal/ipn.php:260 [Thu Dec 12 02:13:37 2013] [error] [client 173.0.82.126] enrol_paypal IPN exception handler: Error writing to database Debug: Column 'useridfrom' cannot be null\nINSERT INTO mdl_message (useridfrom,useridto,subject,fullmessage,fullmessageformat,fullmessagehtml,smallmessage,notification,contexturl,contexturlname,timecreated) VALUES(?,?,?,?,?,?,?,?,?,?,?)\n[array (\n 0 => NULL,\n 1 => '5',\n 2 => 'New enrolment in PAYPAL25',\n 3 => 'Welcome to PAYPAL25!\n\nIf you have not done so already, you should edit your profile page so that we can learn more about you:\n\n http://ci.stronk7.com:8787/~stronk7/integration/user/view.php?id=5',\n 4 => '2',\n 5 => '',\n 6 => '',\n 7 => 0,\n 8 => NULL,\n 9 => NULL,\n 10 => 1386810817,\n)]\nError code: dmlwriteexception\n* line 426 of /lib/dml/moodle_database.php: dml_write_exception thrown\n* line 1089 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()\n* line 1131 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()\n* line 206 of /lib/messagelib.php: call to mysqli_native_moodle_database->insert_record()\n* line 260 of /enrol/paypal/ipn.php: call to message_send()\n Note I'm adding a extra commit to solve both the PHP Warning and the problems with notifications when there is no teacher in the course. ... in progress ...
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -
          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - This is the commit I've added on top of all the branches: http://git.moodle.org/gw?p=integration.git;a=commitdiff;h=32a8bcc4a7e8c80afabbafd80265f2aa0b11c560
          Hide
          skodak Petr Skoda added a comment -

          great, thanks for the commit

          Show
          skodak Petr Skoda added a comment - great, thanks for the commit
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -

          Integrated (24, 25, 26 and master), thanks!

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - Integrated (24, 25, 26 and master), thanks!
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment -

          And passing, tested in all the branches, with provoked exceptions and without, the user ended enrolled always and logs properly got the ipn problems.

          Yay, at last!

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - And passing, tested in all the branches, with provoked exceptions and without, the user ended enrolled always and logs properly got the ipn problems. Yay, at last!
          Hide
          samhemelryk Sam Hemelryk added a comment -

          Thanks for the code, its now upstream!

          Heres a fun trick to try in the spirit of Friday the 13th.
          I hear if you stand in front a mirror, alone, in the dark, and say "Oracle" three times Petr Skoka will appear in the mirror and you'll see him deleting the Oracle driver from Moodle.

          Show
          samhemelryk Sam Hemelryk added a comment - Thanks for the code, its now upstream! Heres a fun trick to try in the spirit of Friday the 13th. I hear if you stand in front a mirror, alone, in the dark, and say "Oracle" three times Petr Skoka will appear in the mirror and you'll see him deleting the Oracle driver from Moodle.

            People

            • Votes:
              9 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Fix Release Date:
                13/Jan/14

                Agile