Moodle
  1. Moodle
  2. MDL-34894

core_course_external_testcase::test_duplicate_course fails on Windows

    Details

    • Rank:
      43419

      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.

        Issue Links

          Activity

          Tim Hunt created issue -
          Hide
          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
          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.
          Tim Hunt made changes -
          Field Original Value New Value
          Fix Version/s STABLE backlog [ 10463 ]
          Priority Minor [ 4 ] Critical [ 2 ]
          Labels triaged
          Assignee moodle.com [ moodle.com ] Jerome Mouneyrac [ jerome ]
          Component/s Backup [ 10068 ]
          Component/s Web Services [ 10425 ]
          Hide
          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
          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
          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
          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.
          Jérôme Mouneyrac made changes -
          Assignee Jerome Mouneyrac [ jerome ] Eloy Lafuente (stronk7) [ stronk7 ]
          Jérôme Mouneyrac made changes -
          Link This issue has a non-specific relationship to MDL-34908 [ MDL-34908 ]
          Hide
          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
          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
          Petr Škoda 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
          Petr Škoda 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
          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
          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
          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
          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
          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
          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
          Jérôme Mouneyrac made changes -
          Link This issue is blocked by MDL-34941 [ MDL-34941 ]
          Hide
          Jérôme Mouneyrac added a comment -

          Created MDL-34941 for the phpunit test fix.

          Show
          Jérôme Mouneyrac added a comment - Created MDL-34941 for the phpunit test fix.
          Hide
          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
          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
          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
          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!
          Tim Hunt made changes -
          Assignee Eloy Lafuente (stronk7) [ stronk7 ] Tim Hunt [ timhunt ]
          Hide
          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
          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.
          Tim Hunt made changes -
          Status Open [ 1 ] Waiting for integration review [ 10010 ]
          Pull Master Diff URL https://github.com/timhunt/moodle/compare/master...MDL-34894
          Pull 2.3 Diff URL https://github.com/timhunt/moodle/compare/MOODLE_23_STABLE...MDL-34894_23
          Pull Master Branch MDL-34894
          Pull from Repository git://github.com/timhunt/moodle.git
          Fix Version/s 2.2.6 [ 12372 ]
          Fix Version/s 2.3.3 [ 12373 ]
          Fix Version/s STABLE backlog [ 10463 ]
          Testing Instructions Run the unit tests on Windows.
          Pull 2.2 Diff URL https://github.com/timhunt/moodle/compare/MOODLE_22_STABLE...MDL-34894_22
          Pull 2.2 Branch MDL-34894_22
          Pull 2.3 Branch MDL-34894_23
          Tim Hunt made changes -
          Fix Version/s 2.2.6 [ 12372 ]
          Pull 2.2 Diff URL https://github.com/timhunt/moodle/compare/MOODLE_22_STABLE...MDL-34894_22
          Pull 2.2 Branch MDL-34894_22
          Eloy Lafuente (stronk7) made changes -
          Currently in integration Yes [ 10041 ]
          Eloy Lafuente (stronk7) made changes -
          Link This issue has a non-specific relationship to MDL-35712 [ MDL-35712 ]
          Hide
          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
          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.
          Eloy Lafuente (stronk7) made changes -
          Status Waiting for integration review [ 10010 ] Integration review in progress [ 10004 ]
          Integrator stronk7
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Integrated (23 & master), thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Integrated (23 & master), thanks!
          Eloy Lafuente (stronk7) made changes -
          Status Integration review in progress [ 10004 ] Waiting for testing [ 10005 ]
          Affects Version/s 2.4 [ 12255 ]
          Hide
          Eloy Lafuente (stronk7) added a comment -

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

          Show
          Eloy Lafuente (stronk7) added a comment - Also note MDL-35714 , that surely will end reverting this once implemented. Ciao
          Eloy Lafuente (stronk7) made changes -
          Link This issue has a non-specific relationship to MDL-35714 [ MDL-35714 ]
          Hide
          Tim Barker added a comment -

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

          Show
          Tim Barker added a comment - It would be good if we could set this VM up on the VM Server for regression testing.
          Tim Barker made changes -
          Tester phalacee
          Jason Fowler made changes -
          Status Waiting for testing [ 10005 ] Testing in progress [ 10011 ]
          Hide
          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
          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.
          Jason Fowler made changes -
          Status Testing in progress [ 10011 ] Tested [ 10006 ]
          Hide
          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
          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
          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
          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
          Eloy Lafuente (stronk7) added a comment -

          Closing as fixed, many thanks for your awesome collaboration.

          Show
          Eloy Lafuente (stronk7) added a comment - Closing as fixed, many thanks for your awesome collaboration.
          Eloy Lafuente (stronk7) made changes -
          Status Tested [ 10006 ] Closed [ 6 ]
          Resolution Fixed [ 1 ]
          Currently in integration Yes [ 10041 ]
          Integration date 05/Oct/12
          Hide
          Eloy Lafuente (stronk7) added a comment -

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

          Show
          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: