SPF not working correctly

[mikernet]

It says "SpamTestSPF, Score: 0" which presumably means it passed SPF testing, yet it still greylists it? Am I missing something?

[SorenR]

It says "SpamTestSPF, Score: 0" which presumably means it passed SPF testing, yet it still greylists it? Am I missing something?

Do you have "Use SPF" test active under Anti-spam?

[mikernet]

Yes

[mikernet]

Does it redo the SPF test for greylisting or reuse the spam test result? If it redoes the test, does it not use the same SPF code?

[SorenR]

Hmm... I believe it MAY reuse SPF result if available but I can't be sure.

Found this in SpamProtection.cpp

Code: Select all

      // Check if the SPF test has succeeded. If so, maybe we should not do
      if (Configuration::Instance()->GetAntiSpamConfiguration().GetBypassGreyListingOnSPFSuccess())
      {
         for(std::shared_ptr<SpamTestResult> testResult : spamTestResults)
         {
            if (testResult->GetTestName() == SpamTestSPF::GetTestName())
            {
               if (testResult->GetResult() == SpamTestResult::Pass)
               {
                  // We should not run grey listing since the SPF test has passed
                  LOG_DEBUG("SPF passed, skipping greylisting.");
                  return true;
               }
            }
         }
      }

So, if you enable Debug logging you should see "SPF passed, skipping greylisting." in the log...

[mikernet]

Well then whatever the issue is, it seems that SPF passes for the purpose of the spam tests, but somehow fails for the purpose of greylisting bypass.

Perhaps the actual test result is Neutral instead of Pass so the spam test score comes out to 0 but still greylists? SpamTestResult can take on the values of Neutral, Pass, and Fail.

[jimimaseye]

Erm...

I think we are looking that too deeply for a problem that doesn't exist. The answer is in your setup and documentation.

I've just looked at your configuration. You have your whitelist entries as

Code: Select all

IP Address: 104.47.* 
IP Address: 209.235.143.14 
IP Address: 40.107.*

Wildcards are not allowed according to https://www.hmailserver.com/documentati ... itelisting:

It's not possible to use wildcards in the IP address

Therefore no match.

(There is no specific page for greylist whitelisting but i assume the same mechanism for parsing the ip addresses is the same and therefore applies. Unless someone can read the code and see different ).

[Entered by mobile. Excuse my spelling.]

[mikernet]

Why would whitelisting have anything to do with the bypass on SPF pass mechanism? It's just ANOTHER mechanism to bypass greylisting, so regardless of whether or not an IP passes the whitelist it should still bypass on SPF pass.

The greylisting whitelist does support wildcards though It was discussed in another thread and I have tested it thoroughly.

P.S. The 40.107.* whitelist entry was added when I posted the OP to alleviate the issue temporarily while we figured this out. It was removed prior to receiving the test email that generated the debug log so that we could see why the SPF bypass mechanism wasn't working. 40.107.* emails go through just fine when the whitelist entry is added.

[RvdH]

Neutral isn't scored on SPF test, because you received "0" score the conclusion is SPF check passed for both test

Code: Select all

   std::set<std::shared_ptr<SpamTestResult> > 
   SpamTestSPF::RunTest(std::shared_ptr<SpamTestData> pTestData)
   {
      std::set<std::shared_ptr<SpamTestResult> > setSpamTestResults;

      String sMessage = "";
      int iScore = 0;

      const IPAddress &originatingAddress = pTestData->GetOriginatingIP();

      if (originatingAddress.IsAny())
         return setSpamTestResults;

      String sExplanation;
      SPF::Result result = SPF::Instance()->Test(originatingAddress.ToString(), pTestData->GetEnvelopeFrom(), sExplanation);
      
      if (result == SPF::Fail)
      {
         // Blocked by SPF.s
         sMessage.Format(_T("Blocked by SPF (%s)"), sExplanation.c_str());
         iScore = Configuration::Instance()->GetAntiSpamConfiguration().GetUseSPFScore();

         std::shared_ptr<SpamTestResult> pResult = std::shared_ptr<SpamTestResult>(new SpamTestResult(GetName(), SpamTestResult::Fail, iScore, sMessage));
         setSpamTestResults.insert(pResult);
      }      
      else if (result == SPF::Pass)
      {
         std::shared_ptr<SpamTestResult> pResult = std::shared_ptr<SpamTestResult>(new SpamTestResult(GetName(), SpamTestResult::Pass, 0, ""));
         setSpamTestResults.insert(pResult);
      }


      return setSpamTestResults;
   }

[mikernet]

Okay, so I'm 99% sure we found the problem. It's right there in the code you posted.

The code considers FAIL and PASS results...but the SPF test CAN apparently return NEUTRAL:

https://github.com/hmailserver/hmailser ... /SPF/SPF.h

The greylisting bypass code subsequently only bypasses on a PASS result, not a NEUTRAL result. The spam scoring mechanism only adds a score if the result is FAIL, not NEUTRAL.

Thus the behavior we are seeing right now is consistent with the way the code is set up, but is that the desirable behavior? I don't think so.

[RvdH]

Okay, so I'm 99% sure we found the problem. It's right there in the code you posted.

The code considers FAIL and PASS results...but the SPF test CAN apparently return NEUTRAL:

https://github.com/hmailserver/hmailser ... /SPF/SPF.h

The greylisting bypass code subsequently only bypasses on a PASS result, not a NEUTRAL result. The spam scoring mechanism only adds a score if the result is FAIL, not NEUTRAL.

Thus the behavior we are seeing right now is consistent with the way the code is set up, but is that the desirable behavior? I don't think so.

But yet it returned a 0 score (as reported in your debug log), so it passed the SPF test

You are mixing up things, yes the SPF library used can return other values, only hmailserver dos not use these... i say it once more, hmailserver spf checking is very basic/limited

[mikernet]

From the info we have (fails to bypass greylisting but does not score in spam test), I'm fairly sure this particular SPF test is coming back neutral for some reason...maybe because of the macro? That would only make sense if it resolved the entire SPF record chain upfront instead of stepping through step-by-step like the examples of the SPF testing tools above though. That would seem like a waste of resources but it's possible I guess?

[mikernet]

The score is only added in the code you posted on a FAIL result, so it would make sense to me that a NEUTRAL result would have a 0 score. Where in the code would a score be added for a NEUTRAL result?

[RvdH]

From the info we have (fails to bypass greylisting but does not score in spam test), I'm fairly sure this particular SPF test is coming back neutral for some reason...maybe because of the macro? That would only make sense if it resolved the entire SPF record chain upfront instead of stepping through step-by-step like the examples of the SPF testing tools above though. That would seem like a waste of resources but it's possible I guess?

I doubt it

[RvdH]

The score is only added in the code you posted on a FAIL result, so it would make sense to me that a NEUTRAL result would have a 0 score. Where in the code would a score be added for a NEUTRAL result?

It isn't....read the code part i pasted, it only returns values for SpamTestResult::Fail or SpamTestResult::Pass, everything else is ignored

[mikernet]

You have to be precise about your definition of "ignored" in this situation though. Yes it is "ignored" in the sense that it is not added to the set of spam test results, but what are the side-effects of that?

One side effect is that this code that you posted:

Code: Select all

      if (Configuration::Instance()->GetAntiSpamConfiguration().GetBypassGreyListingOnSPFSuccess())
      {
         for(std::shared_ptr<SpamTestResult> testResult : spamTestResults)
         {
            if (testResult->GetTestName() == SpamTestSPF::GetTestName())
            {
               if (testResult->GetResult() == SpamTestResult::Pass)
               {
                  // We should not run grey listing since the SPF test has passed
                  LOG_DEBUG("SPF passed, skipping greylisting.");
                  return true;
               }
            }
         }
      }

Will now NOT bypass greylisting since it won't find the SPF test results in the set of results, since it was "ignored".

I can't find the code that outputs the result of the SPF test to the debug log, but I guarantee that it does something similar with a default score of 0, so the score never gets set to anything else.

[mikernet]

Bingo:

Code: Select all

         int totalScoreBefore = iTotalScore;
         for (; iter != iterEnd; iter++)
         {
            std::shared_ptr<SpamTestResult> pResult = (*iter);
            setTotalResult.insert(pResult);

            iTotalScore += pResult->GetSpamScore();
         }

         int totalDiff = iTotalScore - totalScoreBefore;

         String sSpamTestResult;
         sSpamTestResult.Format(_T("Spam test: %s, Score: %d"), sName.c_str(), totalDiff);
         LOG_DEBUG(sSpamTestResult);

         if (iTotalScore >= iMaxScore)
         {
            // Threshold has been reached. No point in running any more tests.
            break;
         }

[mikernet]

That code will clearly output a score of 0 because the test is "ignored" and thus the score difference is 0 after it is run...so we get the behavior I described.

[mikernet]

So, the question becomes: should greylisting bypass on SPF NEUTRAL result as well...I would argue it should. If it isn't failing then don't greylist it.

The second question is, why is the result of the SPF test NEUTRAL and not PASS? I'm not 100% sure what a neutral result even means. From what I can tell, it should simply pass in this case.

[RvdH]

Whatever.... good luck!

Your debug log clearly stated:

Code: Select all

"DEBUG"	83036	"2020-02-25 14:33:15.033"	"Spam test: SpamTestSPF, Score: 0"

When is above sting returned? (hint, check the code i posted earlier)
Bingo... only if the SPF check passed!

That has nothing to do with totalscores or whatsoever....you are losing track it seems

[mikernet]

Haha...I don't really know what to make of "whatever... good luck" - did I upset you or was my "typing tone" off?

I certainly didn't mean it that way so I apologize if that's the case. I wasn't quoting "ignored" to be facetious if that's how that came across <3

[mikernet]

The spam test runner goes test by test, runs it, and then outputs the difference in the total score after each enabled test is run. After the SPF test is run, the total difference is 0, and that's where the debug log line for the SPF test is output. The SPF debug log line gets output regardless of whether the SPF test result is pass, fail, or neutral. In the case of a neutral result, it will output 0.

You can see for yourself here:

https://github.com/hmailserver/hmailser ... Runner.cpp

[mikernet]

That debug line is output in the code I JUST posted above, which uses the difference in the total score after the enabled test is run:

Code: Select all

         sSpamTestResult.Format(_T("Spam test: %s, Score: %d"), sName.c_str(), totalDiff);
         LOG_DEBUG(sSpamTestResult);

That code gets run regardless of whether the test passes, fails, or results in a neutral ignored result.

[mikernet]

Here is the exact line that the test runner code starts, which runs each test and outputs to the debug log based on the difference in the total score after the test is run, irrespective of whether or not the individual test decides to add a test result into the test result set:

https://github.com/hmailserver/hmailser ... er.cpp#L49

[RvdH]

Well that is just plain stupid, but you are right i just checked with one of my domains removing the TXT record and it still returned "Spam test: SpamTestSPF, Score: 0"
In that case the debug log is off no use to find the problem

[mikernet]

To be fair, the debug log didn't say the SPF test passed, it only said that the score it contributed to the spam score was 0, haha. That did make it somewhat difficult to trace the issue though. At least it pointed us in the right direction

[RvdH]

Because of this flaw, i guess without a wireshark analysis of the DNS/SPF lookup we will never know what is going on

[mikernet]

Unfortunately, I don't think I can do a Wireshark on the mail server at the moment.

What information are you hoping to get from a Wireshark trace though? I think the main underlying issue is that a neutral result is not considered a pass for greylisting purposes. Secondary to that is why a neutral result is returned when it shouldn't be. I'm not sure how a wireshark will really help though - won't it just result in us seeing the DNS lookups to olg.ca SPF records? How will that help us figure out why the returned record isn't passing?

[mikernet]

Nevermind, I see how a DNS trace could help - there are a lot more results than just pass/fail/neutral. Hmm...

The SPF checker should probably emit the actual SPF result into the debug log during the check to help narrow things down.

That said, given the limitations of hMailServer SPF testing, I'm of the opinion that a non-fail SPF result should also bypass greylisting.

[SorenR]

Nevermind, I see how a DNS trace could help - there are a lot more results than just pass/fail/neutral. Hmm...

The SPF checker should probably emit the actual SPF result into the debug log during the check to help narrow things down.

That said, given the limitations of hMailServer SPF testing, I'm of the opinion that a non-fail SPF result should also bypass greylisting.

Not everyone would agree with you here... The optimum would be to select "Null" or "Pass" in the configuration of Greylisting.

[mikernet]

Upon further reflection, I'm torn on what appropriate behavior should be here, but I guess you can't go wrong with configurability.

[mattg]

particularly where we could determine whether a '+all' should be a pass or fail

[RvdH]

@mikernet
Can you upgrade to latest beta? (5.6.8 - Build 2494)

If so, i can supply you a custom build that reports SPF test result to narrow down the possible problem

"DEBUG" 6364 "2020-02-27 08:12:36.599" "Spam test: SpamTestHeloHost, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.661" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Spam test: SpamTestSPF, Result: Pass"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Total spam score: 0"

"DEBUG" 6364 "2020-02-27 09:10:47.563" "Spam test: SpamTestHeloHost, Score: 1"
"DEBUG" 6364 "2020-02-27 09:10:47.579" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Spam test: SpamTestSPF, Result: Neutral"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Total spam score: 1"

[SorenR]

@mikernet
Can you upgrade to latest beta? (5.6.8 - Build 2494)

If so, i can supply you a custom build that reports SPF test result to narrow down the possible problem

"DEBUG" 6364 "2020-02-27 08:12:36.599" "Spam test: SpamTestHeloHost, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.661" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Spam test: SpamTestSPF, Result: Pass"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 6364 "2020-02-27 08:12:36.864" "Total spam score: 0"

"DEBUG" 6364 "2020-02-27 09:10:47.563" "Spam test: SpamTestHeloHost, Score: 1"
"DEBUG" 6364 "2020-02-27 09:10:47.579" "Spam test: SpamTestMXRecords, Score: 0"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Spam test: SpamTestSPF, Result: Neutral"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Spam test: SpamTestSPF, Score: 0"
"DEBUG" 6364 "2020-02-27 09:10:47.610" "Total spam score: 1"

Just out of curiosity...

HOW THE H**L do you call LOG_DEBUG() from RMSPF.cpp ??? RMSPF.cpp is written C and LOG_DEBUG() is C++ ... I _have_ looked on the interweb but as I'm not a full time programmer some of the solutions shown are all ελληνικά to me.

[RvdH]

That example I returned only the result that hmailserver uses internally, eg: PASS, FAIL and NEUTRAL

in SpamTestSPF.cpp i created a helper function to parse enum value to string

Code: Select all

   inline const char* ToString(SPF::Result v)
   {
      switch (v)
      {
      case SPF::Neutral:   return "Neutral";
      case SPF::Fail:   return "Fail";
      case SPF::Pass: return "Pass";
      default:      return "Unknown";
      }
   }

After (Line 67)

Code: Select all

SPF::Result result = SPF::Instance()->Test(originatingAddress.ToString(), pTestData->GetEnvelopeFrom(), sExplanation);

I inserted

Code: Select all

LOG_DEBUG(Formatter::Format("Spam test: SpamTestSPF, Result: {0}", ToString(result)));

But we are also able to output the RMSPF library result, in SPF.cpp create a similar helper function to parse enum value to string

Code: Select all

   inline const char* ToString(int v)
   {
      switch (v)
      {
      case SPF_Pass: return "Pass";
      case SPF_SoftFail:   return "SoftFail";
      case SPF_Fail:   return "Fail";
      case SPF_Neutral:   return "Neutral";
      case SPF_None: return "None";
      case SPF_TempError: return "TempError";
      case SPF_PermError: return "PermError";
      default:      return "Unknown";
      }
   }

Then somewhere after the SPFQuery call, in spf.cpp (Line 63)

Code: Select all

int result=SPFQuery(family,BinaryIP,T2A(sSenderEmail),NULL,NULL,NULL,&explain);

insert:

Code: Select all

LOG_DEBUG(Formatter::Format("RMSPF Library, Result: {0}", ToString(result)));

"DEBUG" 396 "2020-03-01 12:34:12.932" "RMSPF Library, Result: Pass"
"DEBUG" 396 "2020-03-01 12:34:12.932" "Spam test: SpamTestSPF, Result: Pass"
"DEBUG" 396 "2020-03-01 12:34:12.932" "Spam test: SpamTestSPF, Score: 0"

[SorenR]

That example I returned only the result that hmailserver uses internally, eg: PASS, FAIL and NEUTRAL

in SpamTestSPF.cpp i created a helper function to parse enum value to string

etc.
etc.

Ah... I figured that much but you are avoiding the real question

How do I use the function/class/namespace thingy LOG_DEBUG() in RMSPF.cpp ?

It would be extremely interesting to be able to output stuff from RMSPF.cpp as it happens, debug the decoding of the SPF data.

It's language like this that have a hard time finding it's way to my head
https://stackoverflow.com/questions/189 ... space-in-c

I got my initial programming skills from a brand spanking new Intel MDS 80, then some Assembler training on an Intel Prompt 80/85 (writing selfmodifying code was great fun), some IBM REXX on our IBM4031 (Did some coding on RELAY that later evolved into IRC) and eventually when the PC was invented some PolyPascal and TurboPascal.

... After that I did not write one single line of code beyond a .BAT file for almost 25 years ...

LOG_DEBUG() is defined in logger.cpp and logger.h