Page MenuHomePhabricator

Duplicate log entries; need to normalise IP addresses when looking up and inserting log entries
Closed, ResolvedPublic2 Estimated Story PointsBUG REPORT

Description

What is the problem?

If you are looking up IPInfo for a log entry where the performer and target are IPv6 address (e.g. an anonymous user creates a User page User:$ipv6_address), you can get duplicate log entries.

For example, user with IP address 2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2 created the page User:2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2. In the logs, I see:

[DBQuery] Wikimedia\Rdbms\Database::selectRow [0.004s] unknown: SELECT  *  FROM logging    WHERE log_type = 'ipinfo' AND log_action = 'view_popup' AND log_actor = 1 AND log_namespace = 2 AND log_title = '2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2' AND (log_timestamp > '20220412091032') AND (log_params LIKE '%ipinfo-view-full%' ESCAPE '`' )  LIMIT 1  
[DBQuery] ManualLogEntry::insert [0s] unknown: INSERT INTO logging (log_type,log_action,log_timestamp,log_actor,log_namespace,log_title,log_page,log_params,log_comment_id) VALUES ('ipinfo','view_popup','20220413091032',1,2,'2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2',0,'a:1:{s:8:"4::level";s:16:"ipinfo-view-full";}',1)
...
[DBQuery] Wikimedia\Rdbms\Database::selectRow [0s] unknown: SELECT  *  FROM logging    WHERE log_type = 'ipinfo' AND log_action = 'view_popup' AND log_actor = 1 AND log_namespace = 2 AND log_title = '2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2' AND (log_timestamp > '20220412091032') AND (log_params LIKE '%ipinfo-view-full%' ESCAPE '`' )  LIMIT 1  
[DBQuery] ManualLogEntry::insert [0s] unknown: INSERT INTO logging (log_type,log_action,log_timestamp,log_actor,log_namespace,log_title,log_page,log_params,log_comment_id) VALUES ('ipinfo','view_popup','20220413091032',1,2,'2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2',0,'a:1:{s:8:"4::level";s:16:"ipinfo-view-full";}',1)

Notice that in the first is looking up '2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2' and the second is looking up '2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2'.

Steps to reproduce problem
  1. From an IPv6 address, go to Special:MyTalk and create the page
    • The IPv6 address you are editing from must be the same as the title of the page.
    • You must be creating the page for the first time.
    • If you don't have an IPv6 address or your local environment does not support it, you can use this script and run something like python3 edit_from_ip.py -u http://localhost:8080/w/api.php -i 2001:df3:9a80::3 -t 2001:df3:9a80::3
  2. Login as someone with IPInfo access and go to Special:Log
  3. There should be an entry for the page you created in step 1
  4. Open the IPInfo popup for that log entry
  5. Look at the IPInfo log (Special:Log?type=ipinfo)

Expected behavior: There is just one entry for the IP you edited from in step 1.
Observed behavior: There are two entries.

Environment

Wiki(s): local docker IP Info 0.0.0 (cc08cea) 18:42, 12 April 2022.

Acceptance criteria

We can no longer produce the bug using those steps

Notes

The function IPUtils::sanitizeIP should help here

Details

Event Timeline

dom_walden renamed this task from Normalise IP addresses when looking up and inserting log entries to Duplicate log entries; need to normalise IP addresses when looking up and inserting log entries.Apr 13 2022, 9:34 AM
AGueyte set the point value for this task to 2.Apr 19 2022, 4:46 PM

So... I have reproduced the steps described above and was not able to reproduce the duplicate log.
Just one log was registered for "view pop up".

Yet, I notice that Mm DB has registered the ipv6 address in capital letters while I used lower case in my test.

I looked into maintenance/sql.php DB, not sqlite.

I'm finding the same as @AGueyte:

  • I followed the reproduction steps, creating the page User talk:2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2 while logged out, with the IP address 2001:8b0:7acf:5d4e:2e09:4dff:fe00:bd2
  • There was no duplicate log line in Special:Log/ipinfo
  • Using wfDebugLog, I confirmed that:
    • the two SQL queries from Logger:debouncedLog were both using log_title = '2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2'
    • the $performer and $target from LogHandler were both 2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2
  • Like @AGueyte, I found that my actor table contained 2001:8B0:7ACF:5D4E:2E09:4DFF:FE00:BD2, and that all IPv6 addresses are stored as upper case

The ActorStore does appear to sanitize IP addresses before insertion into the actor table: https://gerrit.wikimedia.org/g/mediawiki/core/+/fc0c940bd19804c3605bb7aa3433fe0dc80656b9/includes/user/ActorStore.php#592

@dom_walden Could your anon user have been inserted via another route, or a long time ago (if normalization has been added since)?

In any case, I do think we should still fix this by ensuring the IP address is normalized before we look it up from Logger::debouncedLog.

Change 785236 had a related patch set uploaded (by AGueyte; author: AGueyte):

[mediawiki/extensions/IPInfo@master] Normalize IPs before debounceLog

https://gerrit.wikimedia.org/r/785236

Change 785236 merged by jenkins-bot:

[mediawiki/extensions/IPInfo@master] Normalize IPs before debounceLog

https://gerrit.wikimedia.org/r/785236

I cannot reproduce this bug on my local or testwiki.

In case of regression, I looked up IP information for several logs and revisions on my local and testwiki (including IPv4 and IPv6). 1 entry was made for each IP as appropriate.

I was not able to test this on beta as for some reason ipinfo entries are not being recorded there. I assume this is a temporary problem with beta rather than a bug we have introduced.

Test environments:

WhitePhosphorus subscribed.

Looks like the patch was already merged on 25 Apr 2022 and the issue has been resolved.