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

core_course_external_testcase::test_duplicate_course fails on Windows

    Details

      Description

      I was getting really odd unit test failures on Windows.

      The error was

      PHP Warning:  unlink(C:\Temp\phpunitdata_head/temp/backup/ca7db3c6c065317c0993e03a7cada794.log) [<a href='function.unlink'>function.unlink</a>]: Permission denied in C:\Users\tjh238\workspace\moodle_head\lib\moodlelib.php on line 10331

      and once it started, every test after that was failing (about 1000 of them).

      As you can see, absolutely no clue which test was failing (note MDL-34893) so I had to put in my own debugging.

      That let me track it down to core_course_external_testcase::test_duplicate_course. This uses backup and restore code to duplicate a course.

      The reason C:\Temp\phpunitdata_head/temp/backup/ca7db3c6c065317c0993e03a7cada794.log could not be unlinked is because something has that file open, and Windows (unlike Linux) does not let you delete open files.

      What has that file open? Well, backup/util/loggers/file_logger.class.php open the file in the constructor, and only closes it in the destructor.

      The backup code has huge nubmers of circular references between classes, so the file_logger is not garbage-collected until the end of the script. Thus the file stays open.

      You can 'fix' this issue by adding to call to gc_collect_cycles(); at the end of test_duplicate_course. However, I suspect that web services should not be using file_logger. Perhaps error_log_logger would be better. Who knows.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

              Hide
              timhunt Tim Hunt added a comment -

              Increasing priority since this causes unit test failures.

              Assigning to Jerome since this is his test / code.

              Adding Eloy as a watcher, because he wrote the backup code.

              Show
              timhunt Tim Hunt added a comment - Increasing priority since this causes unit test failures. Assigning to Jerome since this is his test / code. Adding Eloy as a watcher, because he wrote the backup code.
              Hide
              timhunt Tim Hunt added a comment -

              Now that I can acutally run the tests, I can see I am getting a real failure from the same code:

              1) core_course_external_testcase::test_create_courses
              invalid_parameter_exception: Invalid parameter value detected (courses => Invalid parameter value detected (startdate => Invalid parameter value detected (Invalid external api parameter: the value is "32882306400", the server was expecting
              "int" type): Invalid external api parameter: the value is "32882306400", the server was expecting "int" type): startdate => Invalid parameter value detected (Invalid external api parameter: the value is "32882306400", the server was expecting "int" type): Invalid external api parameter: the value is "32882306400", the
              server was expecting "int" type)
               
              C:\Users\tjh238\workspace\moodle_head\lib\externallib.php:208
              C:\Users\tjh238\workspace\moodle_head\course\externallib.php:504
              C:\Users\tjh238\workspace\moodle_head\course\tests\externallib_test.php:334
              C:\Users\tjh238\workspace\moodle_head\lib\phpunit\classes\advanced_testcase.php:76
              C:\Program Files (x86)\PHP\phpunit:46
               
              To re-run:
               phpunit core_course_external_testcase course\tests\externallib_test.php

              Let me guess, you are running this test on 64-bit Linux? I am using 64-bit Windows, but the PHP version is x86, so compiled for 32-bit. 32882306400 does not fit in a 32-bit int.

              Show
              timhunt Tim Hunt added a comment - Now that I can acutally run the tests, I can see I am getting a real failure from the same code: 1) core_course_external_testcase::test_create_courses invalid_parameter_exception: Invalid parameter value detected (courses => Invalid parameter value detected (startdate => Invalid parameter value detected (Invalid external api parameter: the value is "32882306400", the server was expecting "int" type): Invalid external api parameter: the value is "32882306400", the server was expecting "int" type): startdate => Invalid parameter value detected (Invalid external api parameter: the value is "32882306400", the server was expecting "int" type): Invalid external api parameter: the value is "32882306400", the server was expecting "int" type)   C:\Users\tjh238\workspace\moodle_head\lib\externallib.php:208 C:\Users\tjh238\workspace\moodle_head\course\externallib.php:504 C:\Users\tjh238\workspace\moodle_head\course\tests\externallib_test.php:334 C:\Users\tjh238\workspace\moodle_head\lib\phpunit\classes\advanced_testcase.php:76 C:\Program Files (x86)\PHP\phpunit:46   To re-run: phpunit core_course_external_testcase course\tests\externallib_test.php Let me guess, you are running this test on 64-bit Linux? I am using 64-bit Windows, but the PHP version is x86, so compiled for 32-bit. 32882306400 does not fit in a 32-bit int.
              Hide
              jerome Jérôme Mouneyrac added a comment - - edited

              Thanks Tim for picking up these two issues.

              • The description seems to be an issue with the backup external function. I'll reassign to Juan/Eloy.
              • Your second comment seems to be a bug with the external functions expecting PARAM_INT for a timestamp.It deserves a full review (PARAM_INT => PARAM_FLOAT for timestamp). I'll write one.

              Till now we've been assigning everything related to web service to me, but from now only assign to me the web service issues related to server/design. We start to reach a stage where issue contributions keep increasing in the tracker for every components. Web service issues related to component web service API should be assigned the the component maintainer or moodle.com.

              Show
              jerome Jérôme Mouneyrac added a comment - - edited Thanks Tim for picking up these two issues. The description seems to be an issue with the backup external function. I'll reassign to Juan/Eloy. Your second comment seems to be a bug with the external functions expecting PARAM_INT for a timestamp.It deserves a full review (PARAM_INT => PARAM_FLOAT for timestamp). I'll write one. Till now we've been assigning everything related to web service to me, but from now only assign to me the web service issues related to server/design. We start to reach a stage where issue contributions keep increasing in the tracker for every components. Web service issues related to component web service API should be assigned the the component maintainer or moodle.com.
              Hide
              timhunt Tim Hunt added a comment -

              Jerome, I assigned it to you because git annotate told me you wrote those unit tests. Don't you feel some responsibility towards the code you wrote?

              Show
              timhunt Tim Hunt added a comment - Jerome, I assigned it to you because git annotate told me you wrote those unit tests. Don't you feel some responsibility towards the code you wrote?
              Hide
              skodak Petr Skoda added a comment - - edited

              eh? $course2['startdate'] = 32882306400; // 01/01/3012
              is clearly out of range of our allowed dates, just fix the dates and done, there is no simple way to work around 32bit limitations in php...

              After the conversion to unsigned ints in 2.3 we can use: Fri, 13 Dec 1901 20:45:54 GMT to Tue, 19 Jan 2038 03:14:07 GMT. In earlier moodle versions it is 01-01-1970 only.

              Show
              skodak Petr Skoda added a comment - - edited eh? $course2 ['startdate'] = 32882306400; // 01/01/3012 is clearly out of range of our allowed dates, just fix the dates and done, there is no simple way to work around 32bit limitations in php... After the conversion to unsigned ints in 2.3 we can use: Fri, 13 Dec 1901 20:45:54 GMT to Tue, 19 Jan 2038 03:14:07 GMT. In earlier moodle versions it is 01-01-1970 only.
              Hide
              jerome Jérôme Mouneyrac added a comment -

              Don't you feel some responsibility towards the code you wrote?

              Second issue (core_course_external_testcase::test_create_courses)
              As Petr mentioned I could have fixed the PHP unit changing the timestamp to a smaller one, but I thought it was a hacky solution (I didn't know we have a timestamp range in Moodle). As you can notice, as soon as I read your issue I wrote a new report: MDL-34908. I had to reinstall a working windows environment and so it took me some time. I tested it this morning, and the fix I posted yesterday in MDL-34908 works fine. I think it is the proper way to resolve this second issue. Note that I fixed it the day you reported it - so I stopped working on Oauth2, didn't fix a blocking bug on Hub, didn't review Juan's mobile code etc...

              First issue (core_course_external_testcase::test_duplicate_course fails on Windows):
              I don't know much about backup. Juan nicely contributed this function, I peer-reviewed it and Eloy integrated it. I'm not an expert of backup, it's why I think your first issue should be assigned to Eloy.

              Cheers,
              Jerome

              Show
              jerome Jérôme Mouneyrac added a comment - Don't you feel some responsibility towards the code you wrote? Second issue (core_course_external_testcase::test_create_courses) As Petr mentioned I could have fixed the PHP unit changing the timestamp to a smaller one, but I thought it was a hacky solution (I didn't know we have a timestamp range in Moodle). As you can notice, as soon as I read your issue I wrote a new report: MDL-34908 . I had to reinstall a working windows environment and so it took me some time. I tested it this morning, and the fix I posted yesterday in MDL-34908 works fine. I think it is the proper way to resolve this second issue. Note that I fixed it the day you reported it - so I stopped working on Oauth2, didn't fix a blocking bug on Hub, didn't review Juan's mobile code etc... First issue (core_course_external_testcase::test_duplicate_course fails on Windows): I don't know much about backup. Juan nicely contributed this function, I peer-reviewed it and Eloy integrated it. I'm not an expert of backup, it's why I think your first issue should be assigned to Eloy. Cheers, Jerome
              Hide
              timhunt Tim Hunt added a comment -

              I'm sorry, Jerome. I had no way of knowing MDL-34908 existed. I just saw your comment saying "in future don't assign these bugs to me". What you did with MDL-34908 is exactly how I would expect a Moodle developer to behave.

              Show
              timhunt Tim Hunt added a comment - I'm sorry, Jerome. I had no way of knowing MDL-34908 existed. I just saw your comment saying "in future don't assign these bugs to me". What you did with MDL-34908 is exactly how I would expect a Moodle developer to behave.
              Hide
              jerome Jérôme Mouneyrac added a comment -

              I created a link to MDL-34908 on this issue yesterday, but I should have posted a comment as the link section changes are not highlighted/emailed and so you had few chances to notice it. So it is where I went wrong too. Thanks for apologising anyway, I appreciate it (it's not sarcastic). Continuing the discussion on MDL-34908

              Show
              jerome Jérôme Mouneyrac added a comment - I created a link to MDL-34908 on this issue yesterday, but I should have posted a comment as the link section changes are not highlighted/emailed and so you had few chances to notice it. So it is where I went wrong too. Thanks for apologising anyway, I appreciate it (it's not sarcastic). Continuing the discussion on MDL-34908
              Hide
              jerome Jérôme Mouneyrac added a comment -

              Created MDL-34941 for the phpunit test fix.

              Show
              jerome Jérôme Mouneyrac added a comment - Created MDL-34941 for the phpunit test fix.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Uhm... MDL-34941 has been integrated already...

              regarding the open logger file... it is strange as far as loggers do not have any circular reference. Note we have one backup/restore_cotroller->destroy() to take rid of the existing ones in plan/tasks/steps/settings... but loggers... uhm.

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Uhm... MDL-34941 has been integrated already... regarding the open logger file... it is strange as far as loggers do not have any circular reference. Note we have one backup/restore_cotroller->destroy() to take rid of the existing ones in plan/tasks/steps/settings... but loggers... uhm.
              Hide
              timhunt Tim Hunt added a comment -

              My guess is:

              • backup/restore_cotroller is part of circular references.
              • backup/restore_cotroller has a non-circular reference to the logger.
              • Therefore, if you never call ->destroy(), the controller is never garbage collected, so the logger is not gced.
              • (This is the real guess) duplicate_course probably does not call ->destroy(). Boom!
              Show
              timhunt Tim Hunt added a comment - My guess is: backup/restore_cotroller is part of circular references. backup/restore_cotroller has a non-circular reference to the logger. Therefore, if you never call ->destroy(), the controller is never garbage collected, so the logger is not gced. (This is the real guess) duplicate_course probably does not call ->destroy(). Boom!
              Hide
              timhunt Tim Hunt added a comment -

              I am bored with this stupid bug causing my unit tests runs to blow up, or alternatively, me committing this extra line into un-related bug-fixes when I do git commit -a. Therefore I am submitting the quick-and-dirty fix for integration. If someone wants to do a more profound fix later, please can they create a new issue for that. Thanks.

              Show
              timhunt Tim Hunt added a comment - I am bored with this stupid bug causing my unit tests runs to blow up, or alternatively, me committing this extra line into un-related bug-fixes when I do git commit -a. Therefore I am submitting the quick-and-dirty fix for integration. If someone wants to do a more profound fix later, please can they create a new issue for that. Thanks.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Integrating this now, I've created MDL-35712 about to properly detect missing calls to ->destroy() on each backup & restore operation and, also, review all core uses.

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Integrating this now, I've created MDL-35712 about to properly detect missing calls to ->destroy() on each backup & restore operation and, also, review all core uses.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Integrated (23 & master), thanks!

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Integrated (23 & master), thanks!
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Also note MDL-35714, that surely will end reverting this once implemented. Ciao

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Also note MDL-35714 , that surely will end reverting this once implemented. Ciao
              Hide
              timb Tim Barker added a comment -

              It would be good if we could set this VM up on the VM Server for regression testing.

              Show
              timb Tim Barker added a comment - It would be good if we could set this VM up on the VM Server for regression testing.
              Hide
              phalacee Jason Fowler added a comment -

              Passing test.

              Although I am unable to run the phpunit tests under windows - I tried, oh boy did I try! - this isn't causing any regressions for the other OS, and after taking to Dan about it, he has indicated it is safe to pass.

              Show
              phalacee Jason Fowler added a comment - Passing test. Although I am unable to run the phpunit tests under windows - I tried, oh boy did I try! - this isn't causing any regressions for the other OS, and after taking to Dan about it, he has indicated it is safe to pass.
              Hide
              poltawski Dan Poltawski added a comment -

              Just commenting about this from Dev chat. Since Jason is struggling to get a working windows environment for this, I think we can set this as passed, as its

              • Not creating regressions on other platforms (at least, MacOSX, Linux)
              • Simple and understandable change
              • Hopefully confirmed by Tim H to be working.
              Show
              poltawski Dan Poltawski added a comment - Just commenting about this from Dev chat. Since Jason is struggling to get a working windows environment for this, I think we can set this as passed, as its Not creating regressions on other platforms (at least, MacOSX, Linux) Simple and understandable change Hopefully confirmed by Tim H to be working.
              Hide
              timhunt Tim Hunt added a comment -

              Yes. Confirmed by me. I upgraded to integration/master yesterday exactly because the unit tests were failing for me again, and that was the quickest way to get this change back into my codebase.

              Show
              timhunt Tim Hunt added a comment - Yes. Confirmed by me. I upgraded to integration/master yesterday exactly because the unit tests were failing for me again, and that was the quickest way to get this change back into my codebase.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Closing as fixed, many thanks for your awesome collaboration.

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Closing as fixed, many thanks for your awesome collaboration.
              Hide
              stronk7 Eloy Lafuente (stronk7) added a comment -

              Note I've reverted this because of MDL-35714 integrated. Ciao

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Note I've reverted this because of MDL-35714 integrated. Ciao

                People

                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved:
                    Fix Release Date:
                    12/Nov/12