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

          Issue Links

            Activity

            timhunt Tim Hunt created issue -
            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.
            timhunt 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
            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.
            jerome Jérôme Mouneyrac made changes -
            Assignee Jerome Mouneyrac [ jerome ] Eloy Lafuente (stronk7) [ stronk7 ]
            jerome Jérôme Mouneyrac made changes -
            Link This issue has a non-specific relationship to MDL-34908 [ MDL-34908 ]
            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
            jerome Jérôme Mouneyrac made changes -
            Link This issue is blocked by MDL-34941 [ MDL-34941 ]
            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!
            timhunt Tim Hunt made changes -
            Assignee Eloy Lafuente (stronk7) [ stronk7 ] Tim Hunt [ timhunt ]
            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.
            timhunt 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
            timhunt 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
            stronk7 Eloy Lafuente (stronk7) made changes -
            Currently in integration Yes [ 10041 ]
            stronk7 Eloy Lafuente (stronk7) made changes -
            Link This issue has a non-specific relationship to MDL-35712 [ MDL-35712 ]
            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.
            stronk7 Eloy Lafuente (stronk7) made changes -
            Status Waiting for integration review [ 10010 ] Integration review in progress [ 10004 ]
            Integrator stronk7
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Integrated (23 & master), thanks!

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Integrated (23 & master), thanks!
            stronk7 Eloy Lafuente (stronk7) made changes -
            Status Integration review in progress [ 10004 ] Waiting for testing [ 10005 ]
            Affects Version/s 2.4 [ 12255 ]
            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
            stronk7 Eloy Lafuente (stronk7) made changes -
            Link This issue has a non-specific relationship to MDL-35714 [ MDL-35714 ]
            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.
            timb Tim Barker made changes -
            Tester phalacee
            phalacee Jason Fowler made changes -
            Status Waiting for testing [ 10005 ] Testing in progress [ 10011 ]
            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.
            phalacee Jason Fowler made changes -
            Status Testing in progress [ 10011 ] Tested [ 10006 ]
            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.
            stronk7 Eloy Lafuente (stronk7) made changes -
            Status Tested [ 10006 ] Closed [ 6 ]
            Resolution Fixed [ 1 ]
            Currently in integration Yes [ 10041 ]
            Integration date 05/Oct/12
            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