LoggedIn and LoggedOut no longer works

[deedey]

Find another bug in this last minor version which integrate the name of the agent instead of his login:
LoggedIn & LoggedOut don't works now. Is it the same for you ?
They works in the previous version.

[ryasmi]

@jlowe64 assigned this to you because I know you're doing some work on the plugin at the moment, hope that's ok 😄

[garemoko]

The last statement I have in my Moodle sandbox with the verb https://brindlewaye.com/xAPITerms/verbs/loggedin/ is 3 months ago. I'm working with that sandbox quite regularly so it seems like this is broken for me too.

[caperneoignis]

I've run in to that problem before. I think it's because the name integration has to be included in the event. I'll take a look to see what I did to fix it. I've seen this before, some where else, when I was including it.

[caperneoignis]

I've seen the fullname function for moodle not work before programming something to run on CLI. I'm looking on Moodle-log-expander Repository.php on line 49-51.

    /**
     * Calls the Moodle core fullname function
     * @param PHPObj $user
     * @return Str
     */
    protected function fullname($user) {
        return fullname($user);
    }

The other question is I see this, $opts['user']->fullname in event.php, if this is being read in like a normal database entry, that maybe a problem because I am unaware of moodle having a fullname field. You may want to do $opts['user']->firstname.' '. $opts['user']->lastname; instead. Or a function call that paste it togather. But that is what I can see from a quick run through. otherwise, I don't see any differences from the previous code, I was running. Unless composer is lying to me, and I'm looking at older code then I think I am. Hopefully, this helps out.

[garemoko]

Other events are using the fullname function; I don't think this is to blame.

$opts['user']->firstname.' '. $opts['user']->lastname; is problematic for people for whom this is not the best way to calculate their fullname.

[caperneoignis]

I can confirm I am having the same issue. I'm looking to see where the break is happening. I am not even seeing the information in the LRS. PHP v. 5.6.19

Moodle (3.0.6 (Build: 20160912):
14 Nov, 12:13 Admin User - Front page System Course viewed The user with id '2' viewed the course with id '1'. web 0:0:0:0:0:0:0:1
14 Nov, 12:13 Admin User - System System User has logged in The user with id '2' has logged in. web 0:0:0:0:0:0:0:1
14 Nov, 12:13 Admin User - System System User logged out The user with id '2' has logged out. web 0:0:0:0:0:0:0:1

LearningLocker v. 1.14.0

LRS statement:

Admin User viewed local test site | 8 seconds ago (Mon, Nov 14, 2016 5:12 PM)
Admin User viewed local test site | 2 minutes ago (Mon, Nov 14, 2016 5:10 PM)
Admin User viewed local test site | 9 minutes ago (Mon, Nov 14, 2016 5:03 PM)

I need to fix the time issue on the LRS, it's currently on ZULU time. But the log in events are not appearing when they should, I do notice a lag when the site is signing in, so there might be a error that is not triggering the debug report to be displayed. Maybe a translation issue? I have time so I'll look through and see what is going on.

EDIT:
Further looking, I see the only statement coming into the LRS is the viewed statement. I don't see the logged_in or logged_out events in the Apache server logs for the LRS. Which means it's not even sending from the LRS. the logged in and logged out are the only two events I can see that are not being posted. Weird.

[caperneoignis]

I found the issue or at least a part of it.

Okay, so after enabling xdebug and stepping through the web calls with xapi enabled with in moodle. I discovered the event is not even being triggered. The event goes through base \core\event\base trigger, and appears to stop at events_trigger_legacy($legacyeventname, $this->get_legacy_eventdata()); on line 809 of base.php. I have break points on both event.php of the MXTranslator\Events\Event and user_loggedin and user_loggedout and none of them trigger during sign-in/out. The store.php file in the main xapi plugin does hit the break point in the constructor and then goes to \tool_log\log\manager.php. It then leaves and goes to the base.php where it stays and does not return for any of the xapi portions. So, something is going on where it's wanting to hang inside base.php and not return back to the xapi plugin to do any of that event recording.

However, on the userloggedin event, it is getting a null value for legacy log. but user logged out is triggering this condition:

if (isset($this->stores['logstore_legacy'])) {
            $this->stores['logstore_legacy']->legacy_add_to_log($courseid, $module, $action, $url, $info, $cm, $user, $ip, $time);
        }

and hits the legacy log portion in base.php in the trigger() function.

Course viewed goes to the public function read() in the translator. But for some reason those two events are not triggering the same response. I will keep looking as to what values are different. Since I finally got xdebug to work with phpstorm and the built in server.

[jlowe64]

great work @caperneoignis!

[caperneoignis]

More details, after many minutes of many moons of stepping through the lines of code, that separate course_viewed event from user_loggedin and user_loggedout, I have determined these items.

1. in \tool_log\log\manager in function process() both logstore_xapi and logstore_standard make the foreach loop on line 83. This is function is called from observer.php in the same namespace. So both of my active logstores are called.
2. To add to this confusion, user_loggedin and user_loggedout are both in a variable array named $allobservers which is a member variable in \core\event\manager and is processed in an aptly named function process_buffers(). This is where it gets weird.

user_loggedin and user_loggedout are both in the array however! The event course_viewed is not! in fact when processing the observingclasses when it gets to \core\event\course_viewed it exits early on line 127. I don't know if that plays a part in this, but I find it weird out of the three events, course_viewed is the only one getting inputted into the LRS from the logstore_xapi plugin. All three events hit the writer function I listed early in \tool_log\log\manager. This is called from line 158 of the \core\event\manager method.

So I can only assume, when it 'writes' it is causing xapi to gloss over the event as already being recorded? Because when I step through all the steps, which is very long and drawn out, so I could have missed something, logstore_xapi pops up all the time. It looks like it's being called every event, however, when I keep stepping through and the page finally loads, that is when the break point i had set in events.php in the translator namespace actually gets triggered.

So the only thing I can think of, is because the two events get called and processed in the buffer in the event\manager.php file, that they don't cause an event trigger within the xapi plugin. I would think while processing the buffers, the plugin would be called then with the $writer->write($event, $this); on line 85 of \tool_log\log\manager. apparently that is not true, and by my observation it's the opposite. Which makes me want to try this with some of the other registered events, to see if things like \core\event\quiz_completed also trigger this. I'll check in a moment to see if events in xapi routes list that are in the $allobservers variable also have the same issue. If so, then i guess that would be the issue. but I need to find other events to prove/disprove my hypothesis.

[caperneoignis]

Okay!

These are the only two events I could find within the array $allobservers

'\core\event\user_loggedin' => 'UserLoggedin',
'\core\event\user_loggedout' => 'UserLoggedout',

The rest of the routs listed in \MXTranslator\Controller are not in that array. Which makes me lean in the direction that the processing of the buffers is what is causing the user_loggedin and user_loggedout to not be processed correctly.

I hope this helps narrow down the issue. Because I'm not sure why its happening and why it's only these two items. I find it quite odd to say the least. But if anyone has any idea of how to fix it, I'll be more then happy to test.

[ryasmi]

Thanks for the additional info @caperneoignis 👍

[caperneoignis]

The plot thickens!

Turned the option to transmit events during a task, option on, and guess what I saw!

(11, '\\core\\event\\course_viewed', 'core', 'viewed', 'course', NULL, NULL, 'r', 2, 2, 50, 1, 2, 1, NULL, 0, 'N;', 1479328557, 'web', '0:0:0:0:0:0:0:1', NULL),
(12, '\\core\\event\\user_loggedout', 'core', 'loggedout', 'user', 'user', 2, 'r', 0, 1, 10, 0, 2, 0, NULL, 0, 'a:1:{s:9:"sessionid";s:26:"rirhfk0lfnumd7p8a772q95fb4";}', 1479328970, 'web', '0:0:0:0:0:0:0:1', NULL),
(13, '\\core\\event\\user_loggedin', 'core', 'loggedin', 'user', 'user', 2, 'r', 0, 1, 10, 0, 2, 0, NULL, 0, 'a:1:{s:8:"username";s:5:"admin";}', 1479328981, 'web', '0:0:0:0:0:0:0:1', NULL),
(14, '\\core\\event\\course_viewed', 'core', 'viewed', 'course', NULL, NULL, 'r', 2, 2, 50, 1, 2, 1, NULL, 0, 'N;', 1479328982, 'web', '0:0:0:0:0:0:0:1', NULL);

But for some reason, this is not sending them out, even on task execution. I'll look to see why that is, maybe it will give me a better view since it's more top down.

[caperneoignis]

Found it!

    /**
     * Reads an object from the store with the given type and query.
     * @param String $type
     * @param [String => Mixed] $query
     * @return PhpObj
     */
    protected function readStoreRecord($type, array $query) {
        $model = $this->store->get_record($type, $query);
        if ($model === false) {
            throw new Exception('Record not found.');
        }
        return $model;
    }

It is throwing an exception on user_loggedin and user_logged out, because it can not find course with id=0.

exact xdebug_message:

Exception: Record not found. in 
admin\tool\log\store\xapi\vendor\learninglocker\moodle-log-expander\src\Repository.php on line 28

Call Stack:
    0.0960     357800   1. {main}() admin\cli\cron.php:0
    0.3240   14443224   2. cron_run() admin\cli\cron.php:61
    1.5872   41770272   3. logstore_xapi\task\emit_task->execute() lib\cronlib.php:75
   10.2480   42150248   4. logstore_xapi\log\store->process_events(???) admin\tool\log\store\xapi\classes\task\emit_task.php:53
   30.1050   42539448   5. LogExpander\Controller->createEvents(???) admin\tool\log\store\xapi\classes\log\store.php:104
   77.3227   42546984   6. LogExpander\Events\Event->read(???) admin\tool\log\store\xapi\vendor\learninglocker\moodle-log-expander\src\Controller.php:66
  169.2059   42554136   7. LogExpander\Repository->readCourse(???) admin\tool\log\store\xapi\vendor\learninglocker\moodle-log-expander\src\Events\Event.php:26
  175.9176   42554168   8. LogExpander\Repository->readObject(???, ???) admin\tool\log\store\xapi\vendor\learninglocker\moodle-log-expander\src\Repository.php:196
  175.9176   42554544   9. LogExpander\Repository->readStoreRecord(???, ???) admin\tool\log\store\xapi\vendor\learninglocker\moodle-log-expander\src\Repository.php:60

So it appears the read course is throwing an error because it can not find the record. I will see if there is a way around that. Maybe a default value?
at line 26.

$model = $this->store->get_record($type, $query);

This is the line that throws. I thought it was weird it kept jumping back from there, even though I was using step over and then step in. Then I saw the exception, under $e.

I will see what I can do to fix it.

UPDATE: Made the fix and included it with my PR in expander.

[ryasmi]

@caperneoignis that is awesome! Really good digging! 👍 ✋ 😄 😸 😃 😺 🎈 I hope those emojis demonstrate how grateful I am that you found the problem

[caperneoignis]

HAhahahaha Thanks @ryansmith94! I appreciate it. It took a minute, I was pretty happy I finally found it.

[bvukas]

is this, or will be, merged? I am waiting for this fix.

[ryasmi]

It will be, I just don't have any time to work on this repository right now unfortunately

[davidpesce]

This is fixed as of v1.2.0. Closing