Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Running through java -jar fake-smtp-server-2.0.3.jar drains all CPU resources #199

Closed
Depact opened this issue May 30, 2023 · 16 comments
Closed

Comments

@Depact
Copy link

Depact commented May 30, 2023

Reproduces for me once several messages is sent.
image

@gessnerfl
Copy link
Owner

I tried to reproduce the issue but for me it is working fine. Can you please explain in more detail what 'once serval messages sent' mean?
I tested the system with roughly 500 messages. Could it be that you send a high number of messages which caused high memory consumption and maybe also high heap and GC activities?

@jessec
Copy link

jessec commented Jun 23, 2023

I had the process running for one day with around 500 emails in queue. And the memory consumed was 1.2G and cpu 273%. Will take a screenshot next time. I restarted the server which solved it.

@jessec
Copy link

jessec commented Jun 26, 2023

image

A restart now caused a database corruption

org.h2.jdbc.JdbcSQLNonTransientException: General error: "org.h2.mvstore.MVStoreException: File corrupted in chunk 30920, expected page length 4..384, got 0 [2.1.214/6]" [50000-214]

org.h2.jdbc.JdbcSQLNonTransientException: General error: "org.h2.mvstore.MVStoreException: File corrupted in chunk 30920, expected page length 4..384, got 0 [2.1.214/6]" [50000-214]

@gessnerfl
Copy link
Owner

@jessec: To be honest I'm a bit confused. Based on your latest screenshot it seems you are running a version 0.1.0 and not version 2.0.3. A restart of the server should reset the whole database as the embedded h2 DB is running in embedded mode. It seems that you are running some kind of custom setup, maybe even with a custom compilation. Could you please describe your setup in more detail including:

  • Operating system version
  • Java version and distribution
  • service configuration (application.yaml)

@etidahouse
Copy link
Contributor

Hello @gessnerfl , @jessec

I'm using version 2.1.0, and I've just seen that I have the same problem.
When I run my unit tests and emails are sent to the server, the CPU increases drastically and does not return to "normal" when the tests are over (only 100 emails are sent, i automatially delete emails after test running with an teardown).

The docker container is launched before testing. The smtp server is launched. If I don't send any e-mail, the CPU never exceeds 10% utilization.

I'm using version 2.1.0 via docker and a mac

I'll try to investigate/profile

Below you will find various information

Docker file

FROM gessnerfl/fake-smtp-server:2.1.0

RUN yum update -y

RUN yum install -y nodejs-1:18.12.1-1.amzn2023.0.3

RUN npm install yarn -g

# The SMTP Server Port used by the Fake SMTP Server
ENV FAKESMTP_PORT=8025

# The following "secrets" are not real ones,
# they are just used for testing purposes
ENV FAKESMTP_AUTHENTICATION_USERNAME=xx
ENV FAKESMTP_AUTHENTICATION_PASSWORD=xx

# Port of the web interface
ENV SERVER_PORT=8080

docker stats informations

image

ps informations

bash-5.2# ps
  PID TTY          TIME CMD
    1 ?        00:16:02 java
  186 ?        00:00:00 ps

spring logs informations


  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.0)

2023-06-28T15:00:00.577Z  INFO 1 --- [           main] de.gessnerfl.fakesmtp.Application        : Starting Application using Java 17.0.7 with PID 1 (/app/classes started by root in /root/dev-mail-sdk/packages/mail-sdk)
2023-06-28T15:00:00.596Z  INFO 1 --- [           main] de.gessnerfl.fakesmtp.Application        : The following 1 profile is active: "default"
2023-06-28T15:00:10.500Z  INFO 1 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-06-28T15:00:11.062Z  INFO 1 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 477 ms. Found 2 JPA repository interfaces.
2023-06-28T15:00:17.002Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2023-06-28T15:00:17.051Z  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-06-28T15:00:17.052Z  INFO 1 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.8]
2023-06-28T15:00:17.633Z  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2023-06-28T15:00:17.648Z  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 16732 ms
2023-06-28T15:00:18.301Z  INFO 1 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2023-06-28T15:00:19.276Z  INFO 1 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn0: url=jdbc:h2:mem:mail user=ADMIN
2023-06-28T15:00:19.290Z  INFO 1 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2023-06-28T15:00:19.395Z  INFO 1 --- [           main] o.s.b.a.h2.H2ConsoleAutoConfiguration    : H2 console available at '/h2-console'. Database available at 'jdbc:h2:mem:mail'
2023-06-28T15:00:20.243Z  INFO 1 --- [           main] o.f.c.internal.license.VersionPrinter    : Flyway Community Edition 9.16.3 by Redgate
2023-06-28T15:00:20.244Z  INFO 1 --- [           main] o.f.c.internal.license.VersionPrinter    : See release notes here: https://rd.gt/416ObMi
2023-06-28T15:00:20.244Z  INFO 1 --- [           main] o.f.c.internal.license.VersionPrinter    :
2023-06-28T15:00:20.308Z  INFO 1 --- [           main] o.f.c.i.database.base.BaseDatabaseType   : Database: jdbc:h2:mem:mail (H2 2.1)
2023-06-28T15:00:20.641Z  INFO 1 --- [           main] o.f.c.i.s.JdbcTableSchemaHistory         : Schema history table "PUBLIC"."flyway_schema_history" does not exist yet
2023-06-28T15:00:20.657Z  INFO 1 --- [           main] o.f.core.internal.command.DbValidate     : Successfully validated 1 migration (execution time 00:00.069s)
2023-06-28T15:00:20.697Z  INFO 1 --- [           main] o.f.c.i.s.JdbcTableSchemaHistory         : Creating Schema History table "PUBLIC"."flyway_schema_history" ...
2023-06-28T15:00:20.950Z  INFO 1 --- [           main] o.f.core.internal.command.DbMigrate      : Current version of schema "PUBLIC": << Empty Schema >>
2023-06-28T15:00:21.677Z  INFO 1 --- [           main] o.f.core.internal.command.DbMigrate      : Migrating schema "PUBLIC" to version "1.1.0 - initial table structure"
2023-06-28T15:00:21.947Z  INFO 1 --- [           main] o.f.core.internal.command.DbMigrate      : Successfully applied 1 migration to schema "PUBLIC", now at version v1.1.0 (execution time 00:01.011s)
2023-06-28T15:00:22.557Z  INFO 1 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2023-06-28T15:00:22.753Z  INFO 1 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 6.2.2.Final
2023-06-28T15:00:22.762Z  INFO 1 --- [           main] org.hibernate.cfg.Environment            : HHH000406: Using bytecode reflection optimizer
2023-06-28T15:00:23.322Z  INFO 1 --- [           main] o.h.b.i.BytecodeProviderInitiator        : HHH000021: Bytecode provider name : bytebuddy
2023-06-28T15:00:24.065Z  INFO 1 --- [           main] o.s.o.j.p.SpringPersistenceUnitInfo      : No LoadTimeWeaver setup: ignoring JPA class transformer
2023-06-28T15:00:24.294Z  INFO 1 --- [           main] org.hibernate.orm.dialect                : HHH035001: Using dialect: org.hibernate.dialect.H2Dialect, version: 2.1.214
2023-06-28T15:00:25.330Z  WARN 1 --- [           main] o.h.b.i.InFlightMetadataCollectorImpl    : HHH000069: Duplicate generator name email_part_generator
2023-06-28T15:00:25.626Z  INFO 1 --- [           main] o.h.b.i.BytecodeProviderInitiator        : HHH000021: Bytecode provider name : bytebuddy
2023-06-28T15:00:29.328Z  INFO 1 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2023-06-28T15:00:29.433Z  INFO 1 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2023-06-28T15:00:32.263Z  INFO 1 --- [           main] o.s.d.j.r.query.QueryEnhancerFactory     : Hibernate is in classpath; If applicable, HQL parser will be used.
2023-06-28T15:00:33.152Z  INFO 1 --- [           main] d.g.f.config.BaseSmtpServerConfig        : Setup simple username and password authentication for SMTP server
2023-06-28T15:00:33.177Z  INFO 1 --- [           main] d.g.fakesmtp.smtp.server.BaseSmtpServer  : SMTP server *:8025 starting
2023-06-28T15:00:33.231Z  INFO 1 --- [erThread *:8025] d.g.fakesmtp.smtp.server.ServerThread    : SMTP server *:8025 started
2023-06-28T15:00:33.822Z  WARN 1 --- [           main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2023-06-28T15:00:34.786Z  INFO 1 --- [           main] o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page: class path resource [static/index.html]
2023-06-28T15:00:40.034Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2023-06-28T15:00:40.642Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8081 (http)
2023-06-28T15:00:40.649Z  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-06-28T15:00:40.649Z  INFO 1 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.8]
2023-06-28T15:00:40.727Z  INFO 1 --- [           main] o.a.c.c.C.[Tomcat-1].[localhost].[/]     : Initializing Spring embedded WebApplicationContext
2023-06-28T15:00:40.727Z  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 672 ms
2023-06-28T15:00:40.819Z  INFO 1 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 15 endpoint(s) beneath base path '/actuator'
2023-06-28T15:00:41.042Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8081 (http) with context path ''
2023-06-28T15:00:41.152Z  INFO 1 --- [           main] de.gessnerfl.fakesmtp.Application        : Started Application in 42.993 seconds (process running for 45.561)
2023-06-28T15:00:41.918Z  INFO 1 --- [     task-pool1] d.g.f.service.EmailRetentionTimer        : Deleted 0 emails which exceeded the maximum number 100 of emails to be stored
2023-06-28T15:03:44.002Z  INFO 1 --- [nio-8080-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-06-28T15:03:44.046Z  INFO 1 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-06-28T15:03:44.564Z  INFO 1 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed initialization in 248 ms
2023-06-28T15:05:42.096Z  INFO 1 --- [     task-pool1] d.g.f.service.EmailRetentionTimer        : Deleted 0 emails which exceeded the maximum number 100 of emails to be stored
2023-06-28T15:10:42.342Z  INFO 1 --- [     task-pool2] d.g.f.service.EmailRetentionTimer        : Deleted 0 emails which exceeded the maximum number 100 of emails to be stored
2023-06-28T15:15:42.630Z  INFO 1 --- [     task-pool1] d.g.f.service.EmailRetentionTimer        : Deleted 0 emails which exceeded the maximum number 100 of emails to be stored

@gessnerfl
Copy link
Owner

@jessec @etidahouse
I'm also trying to reproduce the problem. So far without success. I'm working on a MacBook Pro Late 2019 (2.6GHz 6-Core Intel Core i7). I've tried reproducing it both through the IDE and by running the Docker container. In both cases, the CPU increases slightly when about 50 mails are received and then immediately drops to below 1%. Even after around 500 emails, this remains unchanged.

I used de.gessnerfl.fakesmtp.TestDataCreator to create the emails. I guess this is caused by some specific emails which might result in an endless loop on the server. Can you share more details about your test data.

@gessnerfl
Copy link
Owner

In the meantime I provided version 2.1.1 which contains updates of 3rd party libraries only.

@etidahouse
Copy link
Contributor

The test data is extremely simple, this is only a test to verify the correct operation of a mail-sdk (emails with more complex data are done as integration tests with another mail server).

test('send one simple plain text mail', async () => {
      const { mailStorage, teardown, emailApiUrl } = mockMailClient()

      const mail: Mail = {
          from: 'Wino-System <wino-system@wino.fr>',
          to: ['to@wino.fr'],
          subject: 'test',
          text: 'Hello World !',
      }

      const result = await send({
        mailStorage,
        mail,
      })

      expect(isSuccessful(result)).toStrictEqual(true)
      expect(result).toStrictEqual(successful(expectAnyString()))

      const messageId = result.value ?? ''
      const emails = await retrieveEmailByMessageId(emailApiUrl, messageId)

      expect(emails.content.length).toStrictEqual(1)
      expect(emails.content).toStrictEqual([
        {
          id: expectAnyNumber(),
          fromAddress: 'wino-system@wino.fr',
          toAddress: 'to@wino.fr',
          subject: 'test',
          receivedOn: expectAnyString(),
          rawData: expectAnyString(),
          contents: [{ contentType: 'PLAIN', data: 'Hello World !' }],
          attachments: [],
          inlineImages: [],
          messageId,
        },
      ])

      teardown()
    })

I used an MacBook Pro Apple M1 Pro
I'll ask one of my mates to try it with his MacBook Pro with an Intel chip (just in case)

@slanglade
Copy link

slanglade commented Jul 11, 2023

Hi, I've got the same behaviour with latest version 2.1.2 : java process starts nicely, stay calm even after first mails are received. But sometimes during the night (in my case), CPU usage goes 100% permanently. Nothing in the log, except for the periodic "Deleted 0 emails which exceeded the maximum number 100 of emails to be stored" which continues to be emitted.

I've got two instances of fake-smtp-server on two differents VM (Redhat 6, yes I know...) and both have the same problem.

@jessec
Copy link

jessec commented Jul 28, 2023

@jessec: To be honest I'm a bit confused. Based on your latest screenshot it seems you are running a version 0.1.0 and not version 2.0.3. A restart of the server should reset the whole database as the embedded h2 DB is running in embedded mode. It seems that you are running some kind of custom setup, maybe even with a custom compilation. Could you please describe your setup in more detail including:

  • Operating system version
  • Java version and distribution
  • service configuration (application.yaml)

I'm sorry for the delay. Yes I will try the 2x version. Yes I'm running H2 with a file for persistence. I'm now restarting the server daily to solve the cpu spikes for me this is an acceptable situation, but for other maybe not.

@slanglade
Copy link

Something I noticed (but without being 100% sure) : if I have some mails in the inbox and that it's not empty, the "100% CPU" problem doesn't happen. Could it be some sort of process / loop that goes mad with zero message ?

@gessnerfl
Copy link
Owner

I created a test setup to reproduce the issue. I run the latest version 2.1.3 on an AWS EC2 instance (t4g.small ARM64 2 VCPU, 2GB RAM) with 60% memory allocation for the JVM. In Addition to this I send every 10min 10 emails to the server. This is the server configuration:

server:
  port: 8080
  shutdown: graceful

management:
  server:
    port: 8081
  endpoints:
    web:
      exposure:
        include: '*'

spring:
  profiles:
    active: default

  datasource:
    url: jdbc:h2:mem:mail
    username: admin
    password: Test1234
    driver-class-name: org.h2.Driver

  jpa:
    hibernate:
      ddl-auto: validate

  data:
    web:
      pageable:
        size-parameter: size
        page-parameter: page
        default-page-size: 10
        one-indexed-parameters: false
        max-page-size: 1000

  h2:
    console:
      enabled: true

  mvc:
    hiddenmethod:
      filter:
        enabled: true

  jackson:
    serialization:
      write-dates-as-timestamps: false

springdoc:
  swagger-ui:
    path: /swagger-ui.html

fakesmtp:
  port: 8025
  persistentce:
     maxNumberEmails: 100

So far memory is on a very low level (between 128MB and 220MB). CPU is idling all time. I configured the JVM to create a Heap Dump on OutOfMemoryErrors.. I also installed a monitoring solution to gather near real time metrics.

@Depact / @jessec / @slanglade / @etidahouse Can you please also share more details about your setup (CPU, Memory, Heap, Non Heap Memory). Is it the same for all of you that you have no messages stored as reported by @jessec?

gessnerfl added a commit that referenced this issue Oct 16, 2023
…en_client_stops_sending_data

#199: fix command loop to terminate when no data is sent by client
@gessnerfl
Copy link
Owner

@Depact / @etidahouse / @jessec / @slanglade
I just released version 2.1.4 to fix this issue. I used the test case provided by @etidahouse to check whether the fix solves the problem of draining all CPU resources. The problem was caused by the command loop of an email session not ending if the client stopped providing data and did not send a QuitCommand. With the required migration of the SMTP server implementation in version 2.x, this bug was inadvertently introduced when the code was optimized for better readability.

Please let me know if the issue is resolved so that the issue can be closed.

@etidahouse
Copy link
Contributor

Hello @gessnerfl

The fix works, no more CPU problems and connections are closed correctly (before, I had to force jest to close via --forceExit because sessions were not terminated)

Great job and many thanks ! 🙏 😄

@Depact
Copy link
Author

Depact commented Nov 4, 2023

I tested with latest version and it's not reproduce anymore for me.

@slanglade
Copy link

slanglade commented Nov 4, 2023

Yes indeed, the problem is solved! All the installations on my side are running smoothly since a couple of weeks. Many thanks !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants