SQL Error: 23502, SQLState: 23502

[vobornik]

Hi, I wanted to use the fake-smtp-server for testing Outlook new IMAP account procedure (it unfortunately requires SMTP for new IMAP), and this happened:

root@antix:/tmp# java  -jar fake-smtp-server-2.1.2.jar 

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

2023-08-28T18:56:38.810+02:00  INFO 72533 --- [           main] de.gessnerfl.fakesmtp.Application        : Starting Application v2.1.2 using Java 18.0.2-ea with PID 72533 (/tmp/fake-smtp-server-2.1.2.jar started by root in /tmp)
2023-08-28T18:56:38.811+02:00  INFO 72533 --- [           main] de.gessnerfl.fakesmtp.Application        : The following 1 profile is active: "default"
2023-08-28T18:56:39.284+02:00  INFO 72533 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2023-08-28T18:56:39.316+02:00  INFO 72533 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 28 ms. Found 2 JPA repository interfaces.
2023-08-28T18:56:39.564+02:00  INFO 72533 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2023-08-28T18:56:39.569+02:00  INFO 72533 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-08-28T18:56:39.569+02:00  INFO 72533 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.10]
2023-08-28T18:56:39.602+02:00  INFO 72533 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2023-08-28T18:56:39.603+02:00  INFO 72533 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 770 ms
2023-08-28T18:56:39.644+02:00  INFO 72533 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2023-08-28T18:56:39.731+02:00  INFO 72533 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn0: url=jdbc:h2:mem:mail user=ADMIN
2023-08-28T18:56:39.732+02:00  INFO 72533 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2023-08-28T18:56:39.737+02:00  INFO 72533 --- [           main] o.s.b.a.h2.H2ConsoleAutoConfiguration    : H2 console available at '/h2-console'. Database available at 'jdbc:h2:mem:mail'
2023-08-28T18:56:39.788+02:00  INFO 72533 --- [           main] o.f.c.internal.license.VersionPrinter    : Flyway Community Edition 9.16.3 by Redgate
2023-08-28T18:56:39.788+02:00  INFO 72533 --- [           main] o.f.c.internal.license.VersionPrinter    : See release notes here: https://rd.gt/416ObMi
2023-08-28T18:56:39.788+02:00  INFO 72533 --- [           main] o.f.c.internal.license.VersionPrinter    : 
2023-08-28T18:56:39.793+02:00  INFO 72533 --- [           main] o.f.c.i.database.base.BaseDatabaseType   : Database: jdbc:h2:mem:mail (H2 2.1)
2023-08-28T18:56:39.814+02:00  INFO 72533 --- [           main] o.f.c.i.s.JdbcTableSchemaHistory         : Schema history table "PUBLIC"."flyway_schema_history" does not exist yet
2023-08-28T18:56:39.815+02:00  INFO 72533 --- [           main] o.f.core.internal.command.DbValidate     : Successfully validated 1 migration (execution time 00:00.004s)
2023-08-28T18:56:39.817+02:00  INFO 72533 --- [           main] o.f.c.i.s.JdbcTableSchemaHistory         : Creating Schema History table "PUBLIC"."flyway_schema_history" ...
2023-08-28T18:56:39.827+02:00  INFO 72533 --- [           main] o.f.core.internal.command.DbMigrate      : Current version of schema "PUBLIC": << Empty Schema >>
2023-08-28T18:56:39.830+02:00  INFO 72533 --- [           main] o.f.core.internal.command.DbMigrate      : Migrating schema "PUBLIC" to version "1.1.0 - initial table structure"
2023-08-28T18:56:39.839+02:00  INFO 72533 --- [           main] o.f.core.internal.command.DbMigrate      : Successfully applied 1 migration to schema "PUBLIC", now at version v1.1.0 (execution time 00:00.013s)
2023-08-28T18:56:39.868+02:00  INFO 72533 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2023-08-28T18:56:39.893+02:00  INFO 72533 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 6.2.5.Final
2023-08-28T18:56:39.894+02:00  INFO 72533 --- [           main] org.hibernate.cfg.Environment            : HHH000406: Using bytecode reflection optimizer
2023-08-28T18:56:39.942+02:00  INFO 72533 --- [           main] o.h.b.i.BytecodeProviderInitiator        : HHH000021: Bytecode provider name : bytebuddy
2023-08-28T18:56:39.997+02:00  INFO 72533 --- [           main] o.s.o.j.p.SpringPersistenceUnitInfo      : No LoadTimeWeaver setup: ignoring JPA class transformer
2023-08-28T18:56:40.083+02:00  WARN 72533 --- [           main] o.h.b.i.InFlightMetadataCollectorImpl    : HHH000069: Duplicate generator name email_part_generator
2023-08-28T18:56:40.105+02:00  INFO 72533 --- [           main] o.h.b.i.BytecodeProviderInitiator        : HHH000021: Bytecode provider name : bytebuddy
2023-08-28T18:56:40.409+02:00  INFO 72533 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2023-08-28T18:56:40.419+02:00  INFO 72533 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2023-08-28T18:56:40.542+02:00  INFO 72533 --- [           main] o.s.d.j.r.query.QueryEnhancerFactory     : Hibernate is in classpath; If applicable, HQL parser will be used.
2023-08-28T18:56:40.591+02:00  INFO 72533 --- [           main] d.g.f.config.BaseSmtpServerConfig        : Setup simple username and password authentication for SMTP server
2023-08-28T18:56:40.592+02:00  INFO 72533 --- [           main] d.g.fakesmtp.smtp.server.BaseSmtpServer  : SMTP server *:8025 starting
2023-08-28T18:56:40.595+02:00  INFO 72533 --- [erThread *:8025] d.g.fakesmtp.smtp.server.ServerThread    : SMTP server *:8025 started
2023-08-28T18:56:40.638+02:00  WARN 72533 --- [           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-08-28T18:56:40.731+02:00  INFO 72533 --- [           main] o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page template: index
2023-08-28T18:56:40.916+02:00  INFO 72533 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2023-08-28T18:56:40.944+02:00  INFO 72533 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8081 (http)
2023-08-28T18:56:40.944+02:00  INFO 72533 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-08-28T18:56:40.945+02:00  INFO 72533 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.10]
2023-08-28T18:56:40.946+02:00  INFO 72533 --- [           main] o.a.c.c.C.[Tomcat-1].[localhost].[/]     : Initializing Spring embedded WebApplicationContext
2023-08-28T18:56:40.946+02:00  INFO 72533 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 28 ms
2023-08-28T18:56:40.951+02:00  INFO 72533 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 15 endpoint(s) beneath base path '/actuator'
2023-08-28T18:56:40.965+02:00  INFO 72533 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8081 (http) with context path ''
2023-08-28T18:56:40.973+02:00  INFO 72533 --- [           main] de.gessnerfl.fakesmtp.Application        : Started Application in 2.354 seconds (process running for 2.538)
2023-08-28T18:56:41.506+02:00  INFO 72533 --- [     task-pool1] d.g.f.service.EmailRetentionTimer        : Deleted 0 emails which exceeded the maximum number 100 of emails to be stored
2023-08-28T18:58:46.367+02:00  INFO 72533 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-08-28T18:58:46.367+02:00  INFO 72533 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-08-28T18:58:46.367+02:00  INFO 72533 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 0 ms
2023-08-28T18:59:40.737+02:00  WARN 72533 --- [0.1.10.77:50411] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 23502, SQLState: 23502
2023-08-28T18:59:40.737+02:00 ERROR 72533 --- [0.1.10.77:50411] o.h.engine.jdbc.spi.SqlExceptionHelper   : NULL not allowed for column "MESSAGE_ID"; SQL statement:
insert into email (from_address,message_id,raw_data,received_on,subject,to_address,id) values (?,?,?,?,?,?,?) [23502-214]
2023-08-28T18:59:40.739+02:00 ERROR 72533 --- [0.1.10.77:50411] d.g.fakesmtp.smtp.server.Session         : Unexpected error in the SMTP handler thread

[gessnerfl]

@vobornik it seems you were using the system with a non-compliant client that didn't provide a message ID in the MIME message. Can you please let me know what client software was used in this case to find out if it is a valid use case?

[vobornik]

Hi, I am not surprised... It was a MS Outlook, current version of M365 suite during the initial new IMAP account connect procedure. I needed to fake a SMTP server to pass the initial check (the Outlook does not allow to add an IMAP account without a valid SMTP check). I wanted to let you know that this happens. I personally do not need to correct this, workaround found.

[Szaqku]

It's also possible to reproduce mentioned issue using following command in powershell:

Send-MailMessage -From 'test <test@example.com>' -To 'test <test@example.com>' -Subject 'Subject' -Body "Mail body" -SmtpServer '127.0.0.1' -Port 1025

[aiprat]

Well I ran into the same issue trying out the docker image. I needed this for testing and I cannot change the current implementation to add the MESSAGE_ID.

[gessnerfl]

I did some further research and indeed not all clients provide a message id. Because of this I provided a change making the message id optional. Will be release soon with version 2.1.3