udpapi.UdpApi scheduleNextCommand Command in flight, not scheduling next command .. repeat until ..

[runecalico]

I am not certain on how to accurately describe a root cause, but I can at least give some details on what behaviors I see.

The cli process has been running for a few days, with the last console message over 24 hours ago..

2024-08-07 04:44:13 FINE processing.EpisodeProcessing onHashComputed Requested Data for file with Id 47862: SendFile: true, SendML: false
2024-08-07 04:44:13 FINE processing.EpisodeProcessing processEps Processing file Z:\2-WorkingImport\releases\Hyouka [anidb-8855]\Hyouka - OVA01 - ENG UNCUT 540p WEB H.264 -NanDesuKa (FUNi).mkv with Id 47863
2024-08-07 04:44:15 FINE processing.EpisodeProcessing onHashComputed File Z:\2-WorkingImport\releases\Hyouka [anidb-8855]\Hyouka - OVA01 - ENG UNCUT 540p WEB H.264 -NanDesuKa (FUNi).mkv with Id 47863 has been hashed
2024-08-07 04:44:15 FINE udpapi.UdpApi scheduleNextCommand Command in flight, not scheduling next command
2024-08-07 04:44:15 FINE processing.EpisodeProcessing onHashComputed Requested Data for file with Id 47863: SendFile: true, SendML: false
2024-08-07 04:44:15 INFO processing.EpisodeProcessing processEps Initial Processing done

I'm thinking this means it's finally done processing all the episodes .. but it hasn't stopped or done anything for over 24 hrs .. So digging into the very very large log file ..

At some point in a scan, the # of in-flight must reach some maximum and then after that point it stops attempting to queue them?

2024-08-06 23:21:47 FINEST udpapi.UdpApi scheduleNextCommand 22567 commands in queue. Scheduled next command
2024-08-06 23:21:47 INFO udpapi.UdpApi scheduleCommand Scheduling command Command(action=FILE, identifier=file, tag=12698, needsLogin=true, parameters={fmask=7F0AEAE920, 
2024-08-06 23:21:52 FINE udpapi.UdpApi scheduleNextCommand Command in flight, not scheduling next command

But even after it stopped scheduling the next command it continued to hash files .. would those files be scheduled (assuming it could even recover)?

And at some point we no longer receive replies from AniDB .. This is the last "ParseReply" entry in the log .. which based on the snippet above, was received when we still had .. 22567 commands queued? (am I interpreting that correctly?)

2024-08-06 23:21:47 FINE udpapi.ParseReply parseReply Reply: file:12697-12698 220 FILE\n3178453|15832|263556|17651|0||0|0|e2aaf527|10|very 

The latest download of AniAdd (which is newer then the code you had originally been able to clone), has some messages about pausing for 5 minutes every time the AniDB replies took more then 1 minute, and when the replies take longer then 5 minutes (I think it was that long) it would basically say you needed to re-auth, but whenever I saw that message the session was dead and I had to start over ..

Searching the log reveals we had 12668 ParseReply entries for the 47864 files processed.

I am using the latest 4.0.1 code from main

Thoughts?

[runecalico]

hmm.. looking at the time stamps of the last replies .. they were not that far apart ..

    Line 419139: 2024-08-06 23:21:19 FINE udpapi.ParseReply parseReply Reply: file:12690-12691 220 FILE\n3146921|15832|262945|16312|0||0|1|b93a62c2|10|very 
    Line 419160: 2024-08-06 23:21:23 FINE udpapi.ParseReply parseReply Reply: file:12691-12692 220 FILE\n3178451|15832|262945|17651|0||0|0|6fb76c0c|10|very 
    Line 419186: 2024-08-06 23:21:27 FINE udpapi.ParseReply parseReply Reply: file:12692-12693 220 FILE\n3152827|15832|262945|16037|0||0|4096|d4c99f6b|10|very 
    Line 419212: 2024-08-06 23:21:31 FINE udpapi.ParseReply parseReply Reply: file:12693-12694 220 FILE\n3150336|15832|262946|16312|0||0|1|83917724|10|very 
    Line 419248: 2024-08-06 23:21:35 FINE udpapi.ParseReply parseReply Reply: file:12694-12695 220 FILE\n3178452|15832|262946|17651|0||0|0|0b077536|10|very 
    Line 419283: 2024-08-06 23:21:39 FINE udpapi.ParseReply parseReply Reply: file:12695-12696 220 FILE\n3152828|15832|262946|16037|0||0|4096|fd207597|10|very 
    Line 419320: 2024-08-06 23:21:43 FINE udpapi.ParseReply parseReply Reply: file:12696-12697 220 FILE\n3154703|15832|263556|16312|0||0|1|090d6d31|10|very 
    Line 419351: 2024-08-06 23:21:47 FINE udpapi.ParseReply parseReply Reply: file:12697-12698 220 FILE\n3178453|15832|263556|17651|0||0|0|e2aaf527|10|very 
``

[Tyderion]

could you attach the full log (or maybe, upload it to pastebin or something?) if possible? I know it's huge, but i think it might help me find the error.

It should pause 1h and not 5min (due to expecting a ban/problem to be over after that time), but I reduced it to 5min for testing (which i accidentally comitted). I'll fix that part later tonight, but i'll have to see how i can reproduce this situation. Because it should definitely restart sending commands after it waits for anidb to be back up. I think there is a problem handling commandInFlight after there is an error/ban/long response time. currently it assumes only one command is sent at a time, but this might not actually be true

[runecalico]

2-WorkingImport-AniAddCLI-InitialSort.ps1-8_6_24_9_13_17.zip

[runecalico]

Don't know if it's worth looking at an existing Java Anidb implementation on how they did their UDP/flood protection in case there is something in them that isn't well documented on the anidb side - https://github.com/BeasteyCo/Java-AniDB-API/blob/main/src/net/anidb/udp/UdpConnection.java#L46-L69

[Tyderion]

2-WorkingImport-AniAddCLI-InitialSort.ps1-8_6_24_9_13_17.zip

Thanks, i'll take a lookt at it as soon as I have time.

Don't know if it's worth looking at an existing Java Anidb implementation on how they did their UDP/flood protection in case there is something in them that isn't well documented on the anidb side - https://github.com/BeasteyCo/Java-AniDB-API/blob/main/src/net/anidb/udp/UdpConnection.java#L46-L69

I'll take a look at that. But AniAddCli does not implement any speedup/slowdown of the requests, but that was deliberate and it always does 0.25 req/s, so it should probably not run into flood protection, but maybe i misunderstand something. Here's their definition from https://wiki.anidb.net/UDP_API_Definition#Flood_Protection

A Client MUST NOT send more than one packet every four seconds over an extended amount of time

AniAddCli NEVER sends more than 1 packet every 4 seconds. Maybe they count from "sending reply" -> "receiving next packet" (aniAdd counts from "sending packet" to "sending next packet", so if it takes 1s to receive an reply, the next packet will be sent 3s after it received a reply)

Dropped packets are still taken into account for the packet rate. Meaning if you continuously send packets your client will be banned forever.

For tht reason only 1 command is (or well, should be) "in flight" (i.e. sent, but no answer received), so that even if we run into any kind of flooding issue, it won't cause the application to stay banned for a prolonged time.

But I think it might be good to only expect the reply to be delayed by at most 1min, and if there is no reply for that time, try again. In the log it looks like it sends a command, but never receives a reply, and due to this command being "in flight" (i.e. waiting for reply) it never tries to send the next command and keeps filling up the queue

edit: I will implement this soon, it makes sense that replies can get lost (even without getting banned/flood protected etc), as it is a UDP api, and UDP is a protocol that is "fire-and-forget", i.e. there is no mechanism to ensure that a packet was received (in contrast to TCP). I should've thought of that sooner 🙄

[Tyderion]

@runecalico it now waits for 30s and if no reply is received, it will reschedule the command and send the next one. This fix is of course also in the vNext branch with the local cache.

[runecalico]

I tried the vNext branch (prior to the wait) ..

from the logs it looks like it tried logging in once .. and that's it.

No reply message, no message that I've been banned forever etc. it parsed all the files, but I did not see a single ParseReply message in the logs.... even after it was all done and has been idle for hours.

On a side note, since you are working effectively on a new client, did you register this new client with AniDB?

[Tyderion]

I tried the vNext branch (prior to the wait) ..

from the logs it looks like it tried logging in once .. and that's it.

No reply message, no message that I've been banned forever etc. it parsed all the files, but I did not see a single ParseReply message in the logs.... even after it was all done and has been idle for hours.

Can you tell me how you tried to run it? To be honest, i've only tested it right inside of IntelliJ, so maybe there is a bug when running it from the commandline. What's the command? Did it create the db file? (by default it's named aniAdd.sqlite and should be in the directory where you run the jar file)

On a side note, since you are working effectively on a new client, did you register this new client with AniDB?

yes, it's this one (link only works for me, no idea how that is supposed to work, it's configured to be public but I can't access it with a different account than mine)

[runecalico]

I'm running via a powershell script.

java  --enable-preview -jar $MyJar anidb scan -u $MyAniDBUSer -p $MyAniDBPass -c $MyJarConfig --exit-on-ban --db $MyCache $FileBotSourceDirectory *>&1 | Tee-Object -Append -FilePath $MyScriptOutput

It uses the filename I set for the cache, I did verify it will create one too :)

I'm also wondering if there is some odd behavior when running under powershell/cli as the last run .. seems to have hung right during a rename ..

Unless it's changed on how I need to set logging, I've set this as the logging config using $ENV:LOG_CONFIG_FILE

.level=FINEST
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.SimpleFormatter.format=%1$tF %1$tT %4$s %2$s %5$s%6$s%n

The latest odd result

2024-08-10 07:14:24 TRACE org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl close Closing logical connection
2024-08-10 07:14:24 TRACE org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl close Logical connection closed
2024-08-10 07:14:24 INFO processing.EpisodeProcessing nextStep Finished with Rename for file Z:\2-WorkingImport\tvdb\Nura - Rise of the Yokai Clan [tvdb-171731]\Nura - Rise of the Yokai Clan - S00E06 - Zero Tears Snow.mkv with Id 
407
2024-08-10 07:14:24 FINE processing.EpisodeProcessing finalize File Z:\2-WorkingImport\tvdb\Nura - Rise of the Yokai Clan [tvdb-171731]\Nura - Rise of the Yokai Clan - S00E06 - Zero Tears Snow.mkv with Id 407 done

And this was hours ago .. nothing in the logs since then .. and it doesn't look like it actually renamed the file .. but the file is gone .. so perhaps it had a problem with the move?

[runecalico]

Yep, searched the entire file share ..

I don't seem to be able to find a file that could be that one, and it's not in the recycle/deleted folder either :(

Here is my entire config ..

!!aniAdd.config.AniConfiguration
addToMylist: false
anidbHost: api.anidb.net
anidbPort: 9000
deleteDuplicateFiles: false
duplicatesFolder: null
enableFileMove: true
enableFileRenaming: true
moveDuplicateFiles: false
moveToFolder: null
moveTypeUseFolder: false
moveUnknownFiles: false
movieFolder: null
overwriteMLEntries: false
recursivelyDeleteEmptyFolders: false
renameRelatedFiles: true
renameTypeAniDBFileName: false
setStorageType: INTERNAL
setWatched: false
tagSystemCode: |-
  BaseTVShowPath:="Z:\2-WorkingImport-AniAdd\releases\"
  BaseEnglishTVShowPath:="Z:\2-WorkingImport-English-AniAdd\releases\"
  BaseMoviePath:="Z:\2-WorkingImport-AniAdd\movies\"
  BaseEnglishMoviePath:="Z:\2-WorkingImport-English-AniAdd\movies\"
  ShowTitle:=[%ATe%, %ATr%, %ATk%]
  EpisodeTitle:=[%ETe%, %ETr%, %ETk%]
  ShowTitle:=$repl(%ShowTitle%, "\?|\s*\.+$", "_")
  ShowTitle:=$repl(%ShowTitle%, '[\\":/*|<>?]', " ")
  EpisodeTitle:=$repl(%EpisodeTitle%, '[\\":/*|<>?]', " ")
  ShowTitle:=$repl(%ShowTitle%, "\s+", " ")
  EpisodeTitle:=$repl(%EpisodeTitle%, "\s+", " ")
  ShowTitle:=$repl(%ShowTitle%, "^\s|\s$", "")
  EpisodeTitle:=$repl(%EpisodeTitle%, "^\s|\s$", "")
  ShowTitle:=$repl(%ShowTitle%, "`", "'")
  EpisodeTitle:=$repl(%EpisodeTitle%, "`", "'")
  Trunc(str, len):=$repl(%str%, ".{" $len($repl(%str%, "(.?){" %len% "}$", "")) "}$", "")
  TruncEllipse(str, len):={$len(%str%) = $len($Trunc(%str%, %len%)) ? %str% : $Trunc(%str%, %len%) "…" }
  EpisodeTitle:=$TruncEllipse(%EpisodeTitle%, "24")
  ShowTitleTrunc:=$TruncEllipse(%ShowTitle%, "24")
  Regular:=""
  Special:="S"
  #Separator:=" - "
  SpecialEp:=$repl(%EpNo%, "[1234567890]", "")
  EpNo:=$repl(%EpNo%, "[SCTPO]", "")
  Ver:={%Ver% = "1" ? "" : "v" %Ver% }
  Pad:={%SpecialEp% ? "2" : $max($len(%EpHiNo%), $len(%EpCount%)) }
  Pad:={$match(%EpCount%, "0") ? $max("2", %Pad%) : %Pad% }
  EpNoPad:=$pad(%EpNo%, %Pad%, "0")
  EpNoPad:={%SpecialEp%       ? %EpNoPad%  :  %Regular%   %EpNoPad% }
  EpNoPad:={%SpecialEp% = "S" ? %Special%     %EpNoPad% : %EpNoPad% }
  EpNoPad:={%SpecialEp% = "C" ? %Special% "1" %EpNoPad% : %EpNoPad% }
  EpNoPad:={%SpecialEp% = "T" ? %Special% "2" %EpNoPad% : %EpNoPad% }
  EpNoPad:={%SpecialEp% = "P" ? %Special% "3" %EpNoPad% : %EpNoPad% }
  EpNoPad:={%SpecialEp% = "O" ? %Special% "4" %EpNoPad% : %EpNoPad% }
  EpNoFull:=%Separator% %EpNoPad% %Ver% %Separator%
  GT:="[" [%GTs%, %GTl%] "]"
  Src:="[" $repl(%Source%, "Blu-ray", "BluRay") "]"
  Cen:={%Cen% ? "[Cen]" : "" }
  Res:="[" %FVideoRes% "]"
  VCodec:="[" $repl(%FVCodec%,"H264/AVC","h264") "]"
  ACodec:="[" %FACodec% "]"
  CRC:="[" $uc(%FCrc%) "]"
  FileInfo:=" " %GT% %Src% %Cen% %Res% %VCodec% %CRC%
  MovieTypes:="Movie|OVA"
  IsMovie:={$match(%Type%, %MovieTypes%) ? {%EpCount% = "1" ? {%SpecialEp% ? "" : "1" } : "" } : "" }
  LangTypes:=".*([eE]nglish).*"
  IsEnglish:={$match(%FALng%, %LangTypes%) ? "1" : "" }
  MovieFileName:=%ShowTitle%" - "%FileInfo%
  MovieFileNameMinimal:=%ShowTitleTrunc%" - "%FileInfo%
  TVShowFileName:=%ShowTitle%" - "%EpNoFull%" - "%EpisodeTitle%" - "%FileInfo%
  TVShowFileNameWithoutEpisodeTitle:=%ShowTitle%" - "%EpNoFull%" - "%FileInfo%
  TVShowFileNameMinimal:=%EpNoFull%" - "%FileInfo%
  BasePath:={%IsMovie% ? { %IsEnglish% ? %BaseEnglishMoviePath% : %BaseMoviePath% } : { %IsEnglish% ? %BaseEnglishTVShowPath% : %BaseTVShowPath% } }
  FileName:={%IsMovie% ? %MovieFileName% : %TVShowFileName% }
  PathName:=%BasePath%  %ShowTitle% " [anidb-"%AId%"]"
  PathNameTruncated:=%BasePath%  %ShowTitleTrunc% " [anidb-"%AId%"]"
  # Change FileName based on truncation, will use TVShowFileNameWithoutEpisodeTitle or MovieFileNameMinimal
  CheckPathLengthPad:=$max($len($pad(%PathName% %FileName%,"240","o")) , $len(%PathName% %FileName%))
  FileName:= { %CheckPathLengthPad% = $len(%PathName% %FileName%) ? {%IsMovie% ? %MovieFileNameMinimal% : %TVShowFileNameWithoutEpisodeTitle% } : {%IsMovie% ? %MovieFileName% : %TVShowFileName% } }
  # Change FileName based on truncation, will use TVShowFileNameMinimal or MovieFileNameMinimal
  CheckPathLengthPad:=$max($len($pad(%PathName% %FileName%,"240","o")) , $len(%PathName% %FileName%))
  FileName:= { %CheckPathLengthPad% = $len(%PathName% %FileName%) ? {%IsMovie% ? %MovieFileNameMinimal% : %TVShowFileNameMinimal% } : {%IsMovie% ? %MovieFileNameMinimal% : %TVShowFileNameWithoutEpisodeTitle% } }
  # Change PathName based on truncation will use PathNameTruncated or PathName
  CheckPathLengthPad:=$max($len($pad(%PathName% %FileName%,"240","o")) , $len(%PathName% %FileName%))
  PathName:= { %CheckPathLengthPad% = $len(%PathName% %FileName%) ? %PathNameTruncated% : %PathName% }
tvShowFolder: null
unknownFolder: null

[runecalico]

Java version

PS C:\Users\anime\desktop\scripts> java -version
openjdk version "21.0.3" 2024-04-16 LTS
OpenJDK Runtime Environment Temurin-21.0.3+9 (build 21.0.3+9-LTS)
OpenJDK 64-Bit Server VM Temurin-21.0.3+9 (build 21.0.3+9-LTS, mixed mode, sharing)

[Tyderion]

oh wtf. i'm sorry that this file is gone :(

Could you give me the full log? I looked at the code and I really don't see how it could result in that, as the copy operation has to be successful before the file is deleted (at the only place where it deletes files). I will add an additional check (that the new file exists before the old one is removed), but this seems to be a very weird bug

[runecalico]

2-WorkingImport-AniAddCLI-InitialSort.ps1-8_10_24_6_46_25.zip

[Tyderion]

i just managed to look through the log for a bit and I found this line here which is missing the target file name for the rename:

2024-08-10 07:14:23 FINE processing.FileRenamer renameFile File Z:\2-WorkingImport\tvdb\Nura - Rise of the Yokai Clan [tvdb-171731]\Nura - Rise of the Yokai Clan - S00E06 - Zero Tears Snow.mkv with Id 407 renamed to

There should be target file path there. i.e. something like

2024-08-10 07:14:23 FINE processing.FileRenamer renameFile File [originalPath] with Id [ID] renamed to [targetFilePath]

and For some reason it's empty (or can't be printed), which in both cases would be bad. I have not yet been able to reproduce this behaviour, but I will add an additional check which might work (sometime today probably)