2.1rc2 (suddenly) produces errors from cron.php

Started by m4z, September 26, 2019, 05:02:07 PM

Previous topic - Next topic

m4z

For a few days now, I'm seeing these errors from my production SMF in my lighttpd error log:


2019-09-26 18:50:34: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 18:50:34: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 18:50:34: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 18:50:34: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 19:06:50: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 19:06:50: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 19:06:50: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926
2019-09-26 19:06:50: (mod_fastcgi.c.2702) FastCGI-stderr: PHP Warning:  pg_execute(): Query failed: ERROR:  invalid input syntax for type inet: "" in (redacted)/Sources/Subs-Db-postgresql.php on line 926


At the same time, postgres logs this:

2019-09-26 19:06:50 UTC [27776-9] (redacted)@(redacted) ERROR:  invalid input syntax for type inet: ""
2019-09-26 19:06:50 UTC [27776-10] (redacted)@(redacted) STATEMENT:  INSERT INTO (redacted)smf_log_errors
                                        (id_member, log_time, ip, url, message, session, error_type, file, line, backtrace)
                                VALUES( $1, $2, $3, $4, $5, $6, $7, $8, $9, $10)


These errors always seems to appear in pairs of 4 or 5 and every ~5 to ~30 minutes. Apparently, this is caused by cron.php:

88.0.0.0 (redacted).de - [2019-09-26T19:06:50 +0000] "GET /cron.php?ts=1569524805 HTTP/1.1" 500 80 "https://(redacted).de/index.php?topic=3.new" "Mozilla/5.0 [...] Chrome/77.[...]"


I haven't touched the code in months (I'm running rc2 with a few bugfixes, f.e. for the SearchAPI error). I have however recently installed (Debian 8) software updates which brought minor updates for php and postgres related packages.
I have no clue how to debug this further... :-\
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

Arantor


m4z

id_task |               task_file                |          task_class          |                                                                                                                                                                                                                                                                             task_data                                                                                                                                                                                                                                                                              | claimed_time
---------+----------------------------------------+------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------
     170 | $sourcedir/tasks/CreatePost-Notify.php | CreatePost_Notify_Background | {"msgOptions":{"id":"145","subject":"Re: (redacted)","body":"[spoiler](redacted)[\/spoiler]<br><br>[spoiler][attach id=29](redacted).jpg[\/attach][\/spoiler]","icon":"xx","smileys_enabled":true,"attachments":[],"approved":1,"send_notifications":true},"topicOptions":{"id":41,"board":"4","poll":null,"lock_mode":null,"sticky_mode":null,"mark_as_read":true,"is_approved":true,"redirect_expires":null,"redirect_topic":null},"posterOptions":{"id":1,"name":"m4z","email":"(redacted)","update_post_count":true,"ip":"88.(redacted)"},"type":"reply"} |   1569532007
(1 row)


That post is ~6 days old.
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

Arantor

https://github.com/SimpleMachines/SMF2.1/pull/5222/commits/6e288d5f78e954aacbceb629ce3346d8a1b26cd9 fixes part of the problem, namely the error log itself failing to insert.

But that doesn't resolve the underlying 'why', the reason that task is still there 6 days later is because it's failing, but you don't know what the error is because the error logging fails to log the error. Try that above commit (on its own maybe) and see what happens.

m4z

#4
Correction, I'm seeing the error in both my staging (see the above task) and production forums (with the following task):
id_task |               task_file                |          task_class          |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              task_data                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              | claimed_time
---------+----------------------------------------+------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------
     587 | $sourcedir/tasks/CreatePost-Notify.php | CreatePost_Notify_Background | {"msgOptions":{"id":"551","subject":"Re: (redacted)  &quot;(redacted)\u00b4s (redacted)&quot;","body":"[quote author=(redacted) link=msg=470 date=1569104843](redacted)[\/quote]<br><br>(redacted)[spoiler](redacted)[\/spoiler][\/li]<br>(redacted)[\/li]<br>[\/list]<br><br>","icon":"xx","smileys_enabled":true,"attachments":[],"approved":1,"send_notifications":true},"topicOptions":{"id":79,"board":"20","poll":null,"lock_mode":null,"sticky_mode":null,"mark_as_read":true,"is_approved":true,"redirect_expires":null,"redirect_topic":null},"posterOptions":{"id":3,"name":"(redacted)","email":"(redacted)","update_post_count":true,"ip":"77.(redacted)"},"type":"reply"} |   1569532556
(1 row)


One thing these posts have in common is they both contain spoiler tags (I'm using the only 2.1-ready spoiler mod, YASM), and I installed that mod only a few days ago, so it might be related. However, there are many other posts containing spoiler tags that didn't cause any issues.


[edit: thanks! (and thanks for not saying "don't use rc2, use HEAD"  O:))]

I'm now seeing this in my staging forum:

Art des Fehlers: Kritisch
The database value you're trying to insert does not exist: smiley_set
Function: parsesmileys
http://(redacted)/cron.php
(redacted)/Sources/Subs.php (Zeile 3037)



   3023: // Load the smileys in reverse order by length so they don't get parsed incorrectly.
   3024: if (($temp = cache_get_data('parsing_smileys_' . $user_info['smiley_set'], $cache_time)) == null)
   3025: {
   3026: $result = $smcFunc['db_query']('', '
   3027: SELECT s.code, f.filename, s.description
   3028: FROM {db_prefix}smileys AS s
   3029: JOIN {db_prefix}smiley_files AS f ON (s.id_smiley = f.id_smiley)
   3030: WHERE f.smiley_set = {string:smiley_set}' . (empty($modSettings['smiley_enable']) ? '
   3031: AND s.code IN ({array_string:default_codes})' : '') . '
   3032: ORDER BY LENGTH(s.code) DESC',
   3033: array(
   3034: 'default_codes' => array('>:D', ':D', '::)', '>:(', ':))', ':)', ';)', ';D', ':(', ':o', '8)', ':P', '???', ':-[', ':-X', ':-*', ':\'(', ':-\\',    '^-^', 'O0', 'C:-)', 'O:-)'),
   3035: 'smiley_set' => $user_info['smiley_set'],
   3036: )
==>3037: );
   3038: $smileysfrom = array();
   3039: $smileysto = array();
   3040: $smileysdescs = array();
   3041: while ($row = $smcFunc['db_fetch_assoc']($result))
   3042: {
   3043: $smileysfrom[] = $row['code'];
   3044: $smileysto[] = $smcFunc['htmlspecialchars']($row['filename']);
   3045: $smileysdescs[] = !empty($txt['icon_' . strtolower($row['description'])]) ? $txt['icon_' . strtolower($row['description'])] : $row['description'];
   3046: }
   3047: $smcFunc['db_free_result']($result);
   3048:
   3049: cache_put_data('parsing_smileys_' . $user_info['smiley_set'], array($smileysfrom, $smileysto, $smileysdescs), $cache_time);
   3050: }



And even more in my production forum (there are custom smileys in the prod forum, but not in staging):
Type of error: Cron
8: Undefined index: smiley_set
http://(redacted).de/cron.php
(redacted)/Sources/Subs.php (Line 3011)


Type of error: Cron
8: Undefined index: smiley_set
http://(redacted).de/cron.php
(redacted)/Sources/Subs.php (Line 3024)


Type of error: Cron
8: Undefined index: smiley_set
http://(redacted).de/cron.php
(redacted)/Sources/Subs.php (Line 3035)


And, similar to staging:

Type of error: Critical
The database value you're trying to insert does not exist: smiley_set
Function: parsesmileys
http://(redacted).de/cron.php
(redacted)/Sources/Subs.php (Line 3037)
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

shawnb61

The code has changed a LOT since RC2...   You really need... to... (reads above...)   Nevermind.
Address the process rather than the outcome.  Then, the outcome becomes more likely.   - Fripp

m4z

 :-X

Yeah yeah, I've tested a lot over the last few days, maybe this weekend I'll be courageous enough to update my staging forum...
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

Arantor

So $user_info['smiley_set'] is undefined, which is your core problem, it isn't defined in cron.php, or at least wasn't in RC2, and the reason I didn't encounter it is because I long since removed that particular "feature"...

This does seem like the kind of thing that should have been fixed by now.

m4z

Ok. I updated my staging and prod forums to HEAD, and the problem persists, but I've got another testing forum and the problem didn't exist there until I installed the YASM spoiler mod (and apparently there every post containing a spoiler tag triggers the problem; that certainly didn't happen in my production forum):


id_task |               task_file                |          task_class          |                                                                                                                                                                                                                                                                                     task_data                                                                                                                                                                                                                                                                                      | claimed_time
---------+----------------------------------------+------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------
      33 | $sourcedir/tasks/CreatePost-Notify.php | CreatePost_Notify_Background | {"msgOptions":{"id":"27","subject":"Re: does it goes?","body":" ;D <br>[spoiler]nothing to see here[\/spoiler]<br> 8) ","icon":"xx","smileys_enabled":true,"attachments":[],"approved":1,"send_notifications":true},"topicOptions":{"id":5,"board":"1","poll":null,"lock_mode":null,"sticky_mode":null,"mark_as_read":true,"is_approved":true,"redirect_expires":null,"redirect_topic":null},"posterOptions":{"id":1,"name":"m4z","email":"(redacted)","update_post_count":true,"ip":"82.(redacted)"},"type":"reply"}                                               |   1569603610
      32 | $sourcedir/tasks/CreatePost-Notify.php | CreatePost_Notify_Background | {"msgOptions":{"id":"26","subject":"Re: i r potato","body":"triggered?!<br><br>[spoiler]no[\/spoiler]","icon":"xx","smileys_enabled":true,"attachments":[],"approved":1,"send_notifications":true},"topicOptions":{"id":4,"board":"1","poll":null,"lock_mode":null,"sticky_mode":null,"mark_as_read":true,"is_approved":true,"redirect_expires":null,"redirect_topic":null},"posterOptions":{"id":2,"name":"Bob","email":"(redacted)","update_post_count":true,"ip":"82.(redacted)"},"type":"reply"}                                                            |   1569603605
      35 | $sourcedir/tasks/CreatePost-Notify.php | CreatePost_Notify_Background | {"msgOptions":{"id":"29","subject":"Re: i r potato","body":"A little longer text without any real message<br><br>[spoiler]A secret[\/spoiler]<br><br>More blabla","icon":"xx","smileys_enabled":true,"attachments":[],"approved":1,"send_notifications":true},"topicOptions":{"id":4,"board":"1","poll":null,"lock_mode":null,"sticky_mode":null,"mark_as_read":true,"is_approved":true,"redirect_expires":null,"redirect_topic":null},"posterOptions":{"id":2,"name":"Bob","email":"(redacted)","update_post_count":true,"ip":"82.(redacted)"},"type":"reply"} |            0
(3 rows)

(END)
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

m4z

I have (finally) informed the mod author, but not yet received a response (which is not a complaint, it only has been a couple of days).
"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

Arantor

I don't think this is a bug with the mod. I think this is a bug in SMF.

The issue is that the cron job that does this doesn't have the proper initialisation (in this case, smiley_set) just as before it didn't have the proper setup for user id or timezone or things like that. $user_info['smiley_set'] needs to be set up in cron.php to whatever the default value is from $modSettings.

m4z

"Faith is what you have in things that don't exist."
--Homer Simpson

Es gibt hier im Forum ein deutsches Support-Board!

Advertisement: