solved Odd Problems

perrie
@perrie
7 years ago
435 posts
Looking for clues.

Have a db_create_item listener that has been working fine for weeks. Tracing a production problem and discovered that the listener is getting different information and it appears to be random. The information that is missing (on occasion) is that used for comment threading: comment_thread_id, comment_parent_id and comment_thread_level. The comment_module is jrDiscussion in all cases (of concern).

Threading is enabled, yet sometimes the information comes in $_data and sometimes not. This is new behavior. Here is an fdebug showing what I am talking about.

(2017-10-01T17:19:58-04:00.0.03866800 : 0.084)-(mem: 4MB)-(pid: 4244)-(ip: 75.132.107.114)-(user: TiG)-(uri: POST /comment/comment_save/__ajax=1)
Array
(
    [comment_module] => jrDiscussion
    [comment_item_id] => 34677
    [comment_profile_id] => 2
    [comment_text] => <p>placeholder</p>
    [comment_item_title] => Sophistry
    [_profile_id] => 112
    [_created] => UNIX_TIMESTAMP()
    [_updated] => UNIX_TIMESTAMP()
    [_user_id] => 111
)

(2017-10-01T17:38:36-04:00.0.70442900 : 0.159)-(mem: 4MB)-(pid: 12868)-(ip: 69.253.152.39)-(user: xxxx)-(uri: POST /comment/comment_save/__ajax=1)
Array
(
    [comment_module] => jrDiscussion
    [comment_item_id] => 34686
    [comment_profile_id] => 2
    [comment_text] => <p>...</p>
    [comment_thread_id] => 548517
    [comment_parent_id] => 548598
    [comment_thread_level] => 3
    [comment_item_title] => Who is Carmen Yulin Cruz?
    [_profile_id] => 11
    [_created] => UNIX_TIMESTAMP()
    [_updated] => UNIX_TIMESTAMP()
    [_user_id] => 10
)

The data provided to the listener in these cases should be identically structured. The database does contain these items (verified).

So does anyone have any ideas on what might cause $_data to be populated differently? To sometimes not include the threading fields stored in the database?
updated by @perrie: 01/02/18 02:49:56PM
TiG
TiG
@tig
7 years ago
184 posts
The above post 'Looking for Clues' is really from me.


--
TiG
brian
@brian
7 years ago
10,148 posts
You will not get a comment_parent_id or comment_thread_id if it is the FIRST comment on an item.

Let me know if that helps.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

Understood. The test case is not the first item. It is actually a reply to the second item (i.e. a reply to 2.1).

Note that the data is in the database - it just does not make it to $_data all the time.


--
TiG
brian
@brian
7 years ago
10,148 posts
TiG:
@brian

Understood. The test case is not the first item. It is actually a reply to the second item (i.e. a reply to 2.1).

Note that the data is in the database - it just does not make it to $_data all the time.

Hmmm.. The db_create_item even always passes to the event listeners the data it receives, and the only place I don't see the comment_parent_id or comment_thread_id in the data is if comment threading is enabled, and it's the first comment.

I assume you have threading on? The first example you show is comment _item_id 34677, which is a new comment. The second one is a follow up on comment _item_id 548517, and should be threaded one indent off of 548598. So from here it looks correct.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

The first item is not the first comment. I typed it in myself in reply to comment '2.1' which in addition to its numbering, is visibly indented on the UI and has referback info to its parent (comment 2). Threading is certainly on because the differences are sporadic, the code being executed depends on threading being on and I verified that threading is on. :)

Strange things are happening (database-centric) today and none of it (yet) makes sense from a code perspective. The only change was the creation of a new domain for Beta testing and soon after things started getting weird on the production site.


--
TiG
brian
@brian
7 years ago
10,148 posts
Make sure your beta site is not configured to use your production database in data/config/config.php.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

Just ran another test on the same comment. Note that the info this time came through:

(2017-10-01T19:13:21-04:00.0.23415500 : 0.137)-(mem: 2MB)-(pid: 21816)-(ip: 75.132.107.114)-(user: TiG)-(uri: POST /comment/comment_save/__ajax=1)
Array
(
    [comment_module] => jrDiscussion
    [comment_item_id] => 34677
    [comment_profile_id] => 2
    [comment_text] => <p>This is a reply to comment 2.1</p>
    [comment_thread_id] => 548368
    [comment_parent_id] => 548440
    [comment_thread_level] => 2
    [comment_item_title] => Sophistry
    [_profile_id] => 112
    [_created] => UNIX_TIMESTAMP()
    [_updated] => UNIX_TIMESTAMP()
    [_user_id] => 111
    [comment_hier_id] => 2.1.1
    [comment_hier_count] => 0
)



--
TiG
TiG
TiG
@tig
7 years ago
184 posts
@brian

Will check on that, but note that the Beta site is virgin. I simply created the new name and ran the initialization. Never even signed on to it because attention turned to the comments on production. No files uploaded, nothing configured.


--
TiG
brian
@brian
7 years ago
10,148 posts
TiG:
@brian

Will check on that, but note that the Beta site is virgin. I simply created the new name and ran the initialization. Never even signed on to it because attention turned to the comments on production. No files uploaded, nothing configured.

Did you create using our hosting tools here?


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

Yes. Did the same thing I did to create our alpha site. Used the hosting dashboard to create a new domain named Beta. That is all. No file transfers or anything. I just logged in for the first time and went to the databases. They are the standard, initial databases.

So Beta is simply created. It has had no activity and I never even got to the point of downloading the files locally with PHPStorm. That is, nothing was ever done with Beta.

I would not even bring this up except it is literally the only change we have made to the site in the last few days. And soon after Beta was created strange things started happening in production. I could not begin to explain this.


--
TiG
brian
@brian
7 years ago
10,148 posts
I'm going to guess that is coincidental - I logged in via SSH and I see that the DB's are different. One thing to check is that you've not hardcoded any domains in templates.

We have a lot of users that are using threaded comments, and I'm not aware of any issues with it, so I'm not sure what to recommend without digging into it myself. If you're running any custom modules that also listen for db_create_item, you might try temporarily disabling them. One thing to know about events, is that each module can change the array of data that comes into the listener - i.e. a module that has a higher priority than another module could change the $_data coming in to another module that is lower in priority.

Also - check to see if the issue is only happening to comments on the Discussion module versus other modules (say a blog post) - if that is the case, then the Discussion module could be changing things via a listener.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

Note that no changes have been made to Beta; so no hardcoding there by definition. As for production I unfortunately do not know the history, but I doubt anyone would have hard-coded a tie to a site prefixed with 'beta'.

We are users of threaded comments too and have been happily using them for a very long time. I do not think this is related to code - it seems environmental to me (but I do not have the tools to go beyond the sense).

I have checked the listener (which has also been running just fine) and am out of ideas on that. (I wish it were that easy.)

I believe the problem is only on discussions but I can check that. Given these have been working and we have not changed them, I do not expect I will find anything of value. But our key concern is that comments are not being committed to the database 100% of the time. They are being processed (I have traced this through the code) without error, the SQL Insert is executed, the returns all execute as if everything is fine but the comment is not actually stored in the database. It makes me think we are getting hidden time-outs that are not caught. I have no other reasonable speculation for how a seemingly clean posting of a comment can work through the layers of code with no error conditions triggering and all returns occurring yet the comment never actually was committed.


--
TiG
brian
@brian
7 years ago
10,148 posts
You're not getting timeouts - we'd see those in your data/logs/error_log, and we're not seeing anything there. My guess is there is a listener in FRONT of where you are checking that is removing these keys.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

So much for that hypothesis.

Do not see the problem in blogs (at least could not recreate). There are no jrDiscussion overrides in the code base so the jrDiscussion is pristine (in code) but there are some template overrides (ancient) for jrDiscussion. Ignoring those.

A listener that sporadically removes items from $_data is of course possible, but for some odd reason it would have decided to start this nasty business last night on its own. The missing data though is not the key concern since it does not affect the database processing - the logic does assemble the comment with or without those items (verified).

The key problem is that we started dropping comments last night after the Beta was created and after an entire day of searching do not have clue one as to why they are processed without error through the code yet do not wind up being committed. We are sporadically (it seems) not committing comments to the database. I wish we had changes to back out but the site has been working fine.

Something is preventing select comments from being committed to the db without triggering any error conditions (at least none I can find).


--
TiG

updated by @tig: 10/01/17 05:20:21PM
brian
@brian
7 years ago
10,148 posts
I won't be able to look at this until the AM - I did follow up on a ticket that Perrie opened about needing a master login, so if she can follow up on that AND give me the URL to a discussion that I can test post on I will check it out.

Thanks!


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian - I understand. Here is the deal. Perrie's site is experiencing all sorts of strange problems. In addition to comments not being posted, etc. she cannot run her integrity checks. Having spent the day trying to find anything in the code (especially our code) that could explain this we are left with the fact that this all started after I created the beta site.

So, with that in mind, we are planning on deleting the Beta site and then running every integrity check available to us

Is this a sensible course of action?

We will try to engage Michael to give us guidance. Right now we do not want to do anything without at least an expert weigh in.


--
TiG
brian
@brian
7 years ago
10,148 posts
Michael is traveling and won't be online, and unfortunately I am in the process of moving - I emailed Perrie 3+ hours ago for a master admin login to check it out, but she never replied.


--
Brian Johnson
Founder and Lead Developer - Jamroom
https://www.jamroom.net
TiG
TiG
@tig
7 years ago
184 posts
@brian

Thanks so much from Perrie and gang for taking the time on probably one of your busiest days to give us a much needed dose of your expertise. Appreciated beyond words.


--
TiG
perrie
@perrie
7 years ago
435 posts
Brian,

Would like to second TIG's thank you. It was far beyond your call of duty, especially on moving day. Thank you again!
paul
@paul
7 years ago
4,326 posts
Is this still an issue?
What do I need to do to hopefully see it happening?


--
Paul Asher - JR Developer and System Import Specialist
TiG
TiG
@tig
7 years ago
184 posts
@paul - The immediate issues (quite a few) were all resolved by Brian by clearing the queue which was apparently unusually clogged. How that happened is currently a mystery (and of course a concern). What we would like, if possible, is guidance on how to determine if our queue is in or approaching an abnormal state.

Currently the site is running well and to my knowledge (I will ask Perrie to weigh in) there is nothing unusual to review.

Thanks for checking in on this.


--
TiG
paul
@paul
7 years ago
4,326 posts
Glad its ok atm. Have just had a look at your Dashboard and the queue is empty so things are ok atm.
I'm not sure if there are any alarms that can be set should the queue get large or 'sticks' - I'll take a look, but suggest that you keep an eye on it as part of the general maintenence of the site.


--
Paul Asher - JR Developer and System Import Specialist
TiG
TiG
@tig
7 years ago
184 posts
@paul - Rest assured that we will go to the Queue Viewer if we start seeing anything unusual. :) Thanks.


--
TiG
michael
@michael
7 years ago
7,714 posts
Quote: ....So does anyone have any ideas on what might cause $_data to be populated differently? To sometimes not include the threading fields stored in the database? .....
First guess would be caching. If the datastore contains
....
comment_thread_id] => 548368
    [comment_parent_id] => 548440
    [comment_thread_level] => 2
...
when you're looking at it, but not when your modules run during the event listener phase, my first guess would be caching, perhaps ........ scratch that, my first guess is firing order. If those 3 values are added via a listener, then perhaps your modules listener is firing before the listener that adds those values fires.

Perhaps try adding a lower priority to your module in its _meta() function in include.php
        'priority'    => 50, // LOW load priority (we want other listeners to run first)

Or perhaps try on the 'db_create_item_exit' listener which fires after 'db_create_item' does.
TiG
TiG
@tig
7 years ago
184 posts
@michael

Thanks, but clearing the queue addressed this and all other issues. Very odd though that a clogged queue would manifest as sporadic commit failures and inconsistent data returns. But I suppose if modules are randomly unable to engage we will see data appear in some cases and not in others.

Regardless, thanks for the advice but Brian fixed our environmental problems.


--
TiG

updated by @tig: 10/03/17 10:48:32PM
michael
@michael
7 years ago
7,714 posts
good to hear. weird problem. hard to diagnose.