Sync stops with HTTP status code 500 while apps/gpoddersync/episode_action/create #144

mf8hd · 2023-10-25T22:14:24Z

Issue:

Sync of episodes from "AntennaPod" to "GPodder Sync" stops with Java IO.Exception (on the AntennaPod side) and HTTP status code 500 (on the NextCloud side) while apps/gpoddersync/episode_action/create. Trace: NextCloudTrace.txt

Versions:

NextCloud 25.0.12, PHP 7.4, GPodder Sync 3.7.3, AntennaPod/3.1.1

Solution:

I replaced both occurances of $episodeActionEntity->getGuid() in private function deleteConflictingEpisodeAction() with $episodeActionEntity->getEpisode() in the file EpisodeActionSaver.php (edited version) because findByEpisodeUrl() takes a url and getEpisode() provides it.

Old version:

private function deleteConflictingEpisodeAction(EpisodeActionEntity $episodeActionEntity, string $userId): void
{
	$collidingEpisodeActionId = $this->episodeActionRepository->findByEpisodeUrl($episodeActionEntity->getGuid(), $userId)->getId();
	if ($collidingEpisodeActionId !== $episodeActionEntity->getId()) {
		$this->episodeActionRepository->deleteEpisodeActionByEpisodeUrl($episodeActionEntity->getGuid(), $userId);
	}
}

Edited version:

private function deleteConflictingEpisodeAction(EpisodeActionEntity $episodeActionEntity, string $userId): void
{
	$collidingEpisodeActionId = $this->episodeActionRepository->findByEpisodeUrl($episodeActionEntity->getEpisode(), $userId)->getId();
	if ($collidingEpisodeActionId !== $episodeActionEntity->getId()) {
		$this->episodeActionRepository->deleteEpisodeActionByEpisodeUrl($episodeActionEntity->getEpisode(), $userId);
	}
}

Disclamer:

It works ... for me ... i think ... . I am not a php guy ...

The text was updated successfully, but these errors were encountered:

thrillfall · 2023-10-28T20:52:40Z

Thanks for debugging this. Please provide a test that is going green with your implementation

thawn · 2023-12-02T08:32:06Z

I have the same error. Has the fix been implemented?

thrillfall · 2023-12-02T10:03:06Z

The default identifier is guid. URL is prone to redundancy. The solution might fix your situation but will break it for everyone else.

We need a test that reproduces the exception as to assess this solutions effects

mf8hd · 2023-12-03T17:26:52Z

$this->episodeActionRepository->findByEpisodeUrl($episodeActionEntity->getGuid(), $userId)->getId();

If i read the code above correctly we query the database collumn 'episode' [via the function findByEpisodeUrl()] for a guid [getGuid()]. That can´t be right!

My hack was to query the collumn 'episode' for an episode url. If that´s wrong, then maybe it´s the other way round:

$this->episodeActionRepository->findByGuid($episodeActionEntity->getGuid(), $userId)->getId();

and the line

$this->episodeActionRepository->deleteEpisodeActionByEpisodeUrl($episodeActionEntity->getGuid(), $userId);

should read something like this

$this->episodeActionRepository->deleteEpisodeActionByGuid($episodeActionEntity->getGuid(), $userId);

Does that make any sense ?

thrillfall · 2023-12-03T19:09:42Z

please replicate your current condition in a test (see existing tests for howto set on up) so we can assess the outcome of the proposed changes.

mf8hd · 2023-12-03T19:38:06Z

that´s the difficult part, since my problem ist gone. I´ll try to replicate it ...

thawn · 2023-12-04T06:54:30Z

I will do my best to create such a test case. However, I will need some help:
Could you please point me to what would be a good comparable existing test case?
Also, could you please help me with extracting the debugging information out of the android antenna pod app and out of my nextcloud server (I am admin for that nextcloud instance)?

thawn · 2023-12-04T06:56:32Z

FYI, the problem still persists on my setup, so I should be able to get the required info for a test case.

mf8hd · 2023-12-05T12:08:46Z

About:
This is a way to log the JSON data of /apps/gpoddersync/episode_action/create POST requests on the nextcloud side of things

Versions:
NextCloud 27.1.4, PHP 8.2, NGINX, GPodder Sync 3.8.2, AntennaPod/3.2.0, curl/7.74.0

Caution:
Check all the paths, usernames, commands, etc. and change them to fit your environment !

Overview, aka the short version:

Enable nextcloud debug logging
Create the logfile (with write permission for the webserver user !)
Put logging code in EpisodeActionController.php. (That´s the entry point for /apps/gpoddersync/episode_action/create http requests.)
Restart webserver and php
Create json file with test data
Create nextcloud testuser, with an app password
Test the setup with curl, testuser and file with test data
You should find the test data in the logfile
Sync with AntennaPod and bad data
Bad request logged in nextcloud logfile -> Success

Enable nextcloud logging:
Change or insert these lines in nextclouds config/config.php:

'log_type' => 'file',
'logfile' => '/var/log/nextcloud.log',
'loglevel' => '0',
'log.syslog.format' => '[%reqId%][%remoteAddr%][%user%][%app%][%method%][%url%][%exception%][%data%] %message%',

Create the logfile /var/log/nextcloud.log with sufficient permissions for the webserver:

sudo bash
echo hello > /var/log/nextcloud.log
chown www-data.root /var/log/nextcloud.log

sudo tail -f /var/log/nextcloud.log|grep gpoddersync

Patch /apps-external/gpoddersync/lib/Controller/EpisodeActionController.php
Insert the two lines
use function OCP\Log\logger;
and
logger('gpoddersync')->debug(json_encode($episodeActionsArray));
as shown below.

<?php
declare(strict_types=1);

namespace OCA\GPodderSync\Controller;

use OCA\GPodderSync\Core\EpisodeAction\EpisodeActionSaver;
use OCA\GPodderSync\Db\EpisodeAction\EpisodeActionRepository;
use OCP\AppFramework\Controller;
use OCP\AppFramework\Http\JSONResponse;
use OCP\IRequest;

// *** DEBUG MF8HD ***
use function OCP\Log\logger;

class EpisodeActionController extends Controller {

	private EpisodeActionRepository $episodeActionRepository;
	private string $userId;
	private EpisodeActionSaver $episodeActionSaver;

	protected $request;

	public function __construct(
		string $AppName,
		IRequest $request,
		$UserId,
		EpisodeActionRepository $episodeActionRepository,
		EpisodeActionSaver $episodeActionSaver
	) {
		parent::__construct($AppName, $request);
		$this->episodeActionRepository = $episodeActionRepository;
		$this->userId = $UserId ?? '';
		$this->episodeActionSaver = $episodeActionSaver;
		$this->request = $request;
	}

	/**
	 *
	 * @NoAdminRequired
	 * @NoCSRFRequired
	 *
	 * @return JSONResponse
	 */
	public function create(): JSONResponse {

		$episodeActionsArray = $this->filterEpisodesFromRequestParams($this->request->getParams());

		// *** DEBUG MF8HD ***
		logger('gpoddersync')->debug(json_encode($episodeActionsArray));

		// *** DEBUG MF8HD: The exception occures in the next line ***
		$this->episodeActionSaver->saveEpisodeActions($episodeActionsArray, $this->userId);

		return new JSONResponse(["timestamp" => time()]);
	}

	/**
	 * @NoAdminRequired
	 * @NoCSRFRequired
	 *
	 * @param int $since
	 * @return JSONResponse
	 */
	public function list(int $since = 0): JSONResponse {
		$episodeActions = $this->episodeActionRepository->findAll($since, $this->userId);
		$untypedEpisodeActionData = [];

		foreach ($episodeActions as $episodeAction) {
			$untypedEpisodeActionData[] = $episodeAction->toArray();
		}

		return new JSONResponse([
			"actions" => $untypedEpisodeActionData,
			"timestamp" => time()
		]);
	}

	/**
	 * @param array $data
	 * @return array $episodeActionsArray
	 */
	public function filterEpisodesFromRequestParams(array $data): array {
		return array_filter($data, "is_numeric", ARRAY_FILTER_USE_KEY);
	}
}

Restart webserver and php:

systemctl stop nginx php8.2-fpm
systemctl start nginx php8.2-fpm

Create json testfile gptest.json with the following test content:

[
  {
   "podcast": "https://www.omnycontent.com/d/playlist/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5/podcast.rss",
   "episode": "https://chrt.fm/track/383EG2/traffic.omny.fm/d/clips/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/c9fd6328-74a5-4836-b94c-b0a1012e511b/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5",
   "guid": "c9fd6328-74a5-4836-b94c-b0a1012e511b",
   "action": "play",
   "timestamp": "2023-10-24T16:45:42",
   "started": 1321,
   "position": 1321,
   "total":  1321
  },
  {
   "podcast": "https://www.omnycontent.com/d/playlist/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5/podcast.rss",
   "episode": "https://chrt.fm/track/383EG2/traffic.omny.fm/d/clips/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/c9fd6328-74a5-4836-b94c-b0a1012e511b/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5",
   "guid": "c9fd6328-74a5-4836-b94c-b0a1012e511b",
   "action": "delete",
   "timestamp": "2023-10-24T16:45:44"
  },
  {
   "podcast": "https://www.omnycontent.com/d/playlist/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5/podcast.rss",
   "episode": "https://chrt.fm/track/383EG2/traffic.omny.fm/d/clips/9c074afa-3313-47e8-b802-a9f900789975/09af2160-238f-48b2-b20b-ad4b00ebd8e7/c9fd6328-74a5-4836-b94c-b0a1012e511b/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5",
   "guid": "c9fd6328-74a5-4836-b94c-b0a1012e511b",
   "action": "delete",
   "timestamp": "2023-10-24T16:45:44"
  }
]

Create testuser in nextcloud:
Create testuser USERNAME
Create app password for testuser USERNAME

Test with curl:

curl -u USERNAME:APP-PASSWORD-FOR-USERNAME-AND-CURL -X POST -H "Content-Type: application/json"  -d @gptest.json https://YOUR.SERVER.DOMAIN/YOUR-NEXTCLOUD/index.php/apps/gpoddersync/episode_action/create

Result in /var/log/nextcloud.log:

{"reqId":"Z1a1c6Z4cIj6HaQusiBI","level":0,"time":"2023-12-05T10:02:17+00:00","remoteAddr":"127.0.0.1","user":"USERNAME","app":"gpoddersync","method":"POST","url":"/owncloud/index.php/apps/gpoddersync/episode_action/create","message":"[{\"podcast\":\"https:\\/\\/www.omnycontent.com\\/d\\/playlist\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\\/podcast.rss\",\"episode\":\"https:\\/\\/chrt.fm\\/track\\/383EG2\\/traffic.omny.fm\\/d\\/clips\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/c9fd6328-74a5-4836-b94c-b0a1012e511b\\/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\",\"guid\":\"-c9fd6328-74a5-4836-b94c-b0a1012e511b\",\"action\":\"play\",\"timestamp\":\"2023-10-24T16:45:42\",\"started\":1321,\"position\":1321,\"total\":1321},{\"podcast\":\"https:\\/\\/www.omnycontent.com\\/d\\/playlist\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\\/podcast.rss\",\"episode\":\"https:\\/\\/chrt.fm\\/track\\/383EG2\\/traffic.omny.fm\\/d\\/clips\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/c9fd6328-74a5-4836-b94c-b0a1012e511b\\/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\",\"guid\":\"-c9fd6328-74a5-4836-b94c-b0a1012e511b\",\"action\":\"delete\",\"timestamp\":\"2023-10-24T16:45:44\"},{\"podcast\":\"https:\\/\\/www.omnycontent.com\\/d\\/playlist\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\\/podcast.rss\",\"episode\":\"https:\\/\\/chrt.fm\\/track\\/383EG2\\/traffic.omny.fm\\/d\\/clips\\/9c074afa-3313-47e8-b802-a9f900789975\\/09af2160-238f-48b2-b20b-ad4b00ebd8e7\\/c9fd6328-74a5-4836-b94c-b0a1012e511b\\/audio.mp3?utm_source=Podcast&in_playlist=b86dddc1-67a5-41c2-a13c-ad4b00ebd8f5\",\"guid\":\"-c9fd6328-74a5-4836-b94c-b0a1012e511b\",\"action\":\"delete\",\"timestamp\":\"2023-10-24T16:45:44\"}]","userAgent":"curl/7.74.0","version":"27.1.4.1","data":{"app":"gpoddersync"}}

Conclusion:
You should see the postcast episodes that prevent syncing (and several others) in the nextcloud logfile before the exeption occures. Then you can put the suspicious episode data (reformated !) in the gptest.json file and try again with curl.
You can check the database table oc_gpodder_episode_action in your nextcloud database for the podcast episodes that made it into the database.

mf8hd · 2023-12-05T21:24:21Z

Meanwhile:
I can reproduce the error/exception with the following json testfile:

[
  {
   "podcast": "https://podcast1",
   "episode": "https://episode1",
   "guid": "guid1",
   "action": "play",
   "timestamp": "2023-10-24T16:45:42",
   "started": 1321,
   "position": 1321,
   "total":  1321
  },
  {
   "podcast": "https://podcast1",
   "episode": "https://episode1",
   "guid": "guid2",
   "action": "play",
   "timestamp": "2023-10-24T16:45:42",
   "started": 1321,
   "position": 1321,
   "total":  1321
  },
  {
   "podcast": "https://podcast1",
   "episode": "https://episode2",
   "guid": "guid1",
   "action": "play",
   "timestamp": "2023-10-24T16:45:42",
   "started": 1321,
   "position": 1321,
   "total":  1321
  },
  {
   "podcast": "https://podcast1",
   "episode": "https://episode2",
   "guid": "guid2",
   "action": "play",
   "timestamp": "2023-10-24T16:45:42",
   "started": 1321,
   "position": 1321,
   "total":  1321
  }
]

The testfile contains all permutations of two episodes and two guids for one podcast.

The exception vanishes when i use the hack from my initial post (with getEpisode()).
Now i´ll try to make a working version with getGuid().

thawn · 2023-12-06T07:42:25Z

@mf8hd thanks a lot for the detailed information! I will use that to get the log data for my setup - however I won't have time before the weekend. Happy coding - it sounds like you are getting close to a solution :-)

LinAGKar · 2023-12-22T09:25:58Z

My impression is that @mf8hd's original solution is actually the correct one. That function (deleteConflictingEpisodeAction) will be hit when you're trying to add an episode action with a guid the already exists in the DB, and a URL that also already exists but on a different row. So it I understand things correctly, in the above example, what will happen is:

For the first item:
No item with guid 'guid1' and episode 'https://episode1' exists. So it inserts them as row 1.

For the second item:
A row with episode 'https://episode1' already exists, but there is no row with guid 'guid2'. So it finds row 1 by episode, and changes its guid to 'guid2'.

For the third item:
No item with guid 'guid1' or episode 'https://episode2' exists. So it inserts them as row 2.

For the fourth item:
A row with episode 'guid2' already exists. So it finds row 1 by episode and tries to change its episode to 'https://episode2'. But there is already a different row with that episode. So deleteConflictingEpisodeAction is called in order to delete the conflicting row, by episode. And it takes the guid value from the item, and tries to search for it in the episode column, which of course doesn't find a match. Thus it gets NULL, and then tries to call getId on NULL.

If I understand things correctly, the function should be using getEpisode, in order to work as intended. In which case it would find row 2 by episode, delete it, and then be able to change episode on row 1 to 'https://episode2'.

The test testDoNotFailToUpdateEpisodeActionByGuidIfThereIsAnotherWithTheSameValueForEpisodeUrl doesn't trip because the item it tries to save at https://github.com/thrillfall/nextcloud-gpodder/blob/main/tests/Integration/EpisodeActionSaverGuidBackwardCompatibilityTest.php#L84C84-L84C100 has the same value for the guid and episode, so it ends up working correctly anyway.

thrillfall · 2024-01-07T16:10:30Z

please replicate your current condition in a test (see existing tests for howto set on up) so we can assess the outcome of the proposed changes.

in a pull request please. Thanks

fix #144

thrillfall closed this as completed Nov 9, 2023

thrillfall reopened this Dec 2, 2023

LinAGKar mentioned this issue Jan 8, 2024

Fix getId() on null in deleteConflictingEpisodeAction #152

Merged

thrillfall closed this as completed in #152 Jan 12, 2024

thrillfall added a commit that referenced this issue Jan 12, 2024

release 3.8.3

9c1922a

fix #144

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Sync stops with HTTP status code 500 while apps/gpoddersync/episode_action/create #144

Sync stops with HTTP status code 500 while apps/gpoddersync/episode_action/create #144

mf8hd commented Oct 25, 2023

thrillfall commented Oct 28, 2023

thawn commented Dec 2, 2023

thrillfall commented Dec 2, 2023

mf8hd commented Dec 3, 2023

thrillfall commented Dec 3, 2023

mf8hd commented Dec 3, 2023

thawn commented Dec 4, 2023

thawn commented Dec 4, 2023

mf8hd commented Dec 5, 2023

mf8hd commented Dec 5, 2023

thawn commented Dec 6, 2023

LinAGKar commented Dec 22, 2023 •

edited

Loading

thrillfall commented Jan 7, 2024 •

edited

Loading

Sync stops with HTTP status code 500 while apps/gpoddersync/episode_action/create #144

Sync stops with HTTP status code 500 while apps/gpoddersync/episode_action/create #144

Comments

mf8hd commented Oct 25, 2023

Issue:

Versions:

Solution:

Disclamer:

thrillfall commented Oct 28, 2023

thawn commented Dec 2, 2023

thrillfall commented Dec 2, 2023

mf8hd commented Dec 3, 2023

thrillfall commented Dec 3, 2023

mf8hd commented Dec 3, 2023

thawn commented Dec 4, 2023

thawn commented Dec 4, 2023

mf8hd commented Dec 5, 2023

mf8hd commented Dec 5, 2023

thawn commented Dec 6, 2023

LinAGKar commented Dec 22, 2023 • edited Loading

thrillfall commented Jan 7, 2024 • edited Loading

LinAGKar commented Dec 22, 2023 •

edited

Loading

thrillfall commented Jan 7, 2024 •

edited

Loading